【原創】公司自研緩存系統UPU的總結
公司自主研發了這樣一個緩存系統（名爲 UPU），規格以下：數據庫
- 同機房間的兩個 UPU 互爲主備，但同一時刻只有一個 UPU 經過 keepalived 虛地址對外提供服務，主備切換也是經過 keepalived 實現；
- 同一（邏輯）域內的所有 UPU 造成集羣，集羣間經過 Erlang/OTP 內置的 Mnesia 數據庫完成數據同步；
- UPU 集羣不存在主的概念，故能夠在集羣中的任意節點上進行數據更新操做；
- 能夠進行多級域的 UPU 級聯；
- 業務的數據更新均在本地進行，但數據會向頂級域同步；
- 業務的數據查詢均在本地進行，但會根據具體的請求類型決定是否還向頂級域查詢；
UPU 服務器部署架構圖
UPU 服務器內部結構（Erlang 監督樹結構 ）緩存
libupu（客戶端庫）的結構設計
這套系統存在的部分問題：服務器
- UPU 自己不支持針對緩存消息的超時控制，而是依賴於業務程序本身的控制。在業務自身發生異常的狀況下，可能出現數據的不一致或殘留（已經過其餘方法規避）；
- UPU 的數據同步功能依賴於 Erlang/OTP 內置的 Mnesia 數據庫，官方明確說明在發生網絡分區時，可能會致使數據不一致，原開發人員原本打算採用環形複製來解決集羣數據多寫問題，但最終沒有實現；
- 在 UPU 級聯狀況下，級聯相關配置是手動寫死在配置文件中的，在出現異常時，只能經過修改配置並重啓服務的方式進行恢復（應該能夠經過 Erlang 的內部方法進行解決）；
- UPU 集羣功能借用了 RabbitMQ 中的相應實現，並進行了必定程度的簡化，可能存在部分功能缺失或不完備（能夠經過對比 RabbitMQ 的源碼比較分析並解決）；
- 心跳保活功能存在問題。具體表現爲，級聯 UPU 之間互發心跳請求和應答時，都以自身狀態進行斷定，即收到對方發來的請求也不認爲對方是活躍的，只有對方回覆應答時才認爲保活成功，這種實現方式顯然不合理；
- libupu（業務使用的客戶端庫）中斷定心跳超時的時間值，與 UPU 服務器側的斷定時間值不一樣，這應該是開發人員疏忽致使，但該問題會致使業務在實際使用中遇到部分信息被莫名刪除的問題；
- 日誌輸出不夠清晰直觀。測試以及運維人員沒法直接經過日誌確認當前的執行流程和結果。日誌只有開發人員才能看懂（部分日誌不看代碼都不明白到底在幹啥）；
- 因爲 UPU 原開發人員離職，後續的維護人員彷佛沒法真正領悟其設計實現，相關的功能開發更像是在"打補丁"；
開發人員從這套系統中能夠學到什麼：cookie
- 監督結構的設計，進程動態起停的控制；
- 有助於對 ETS 和 Mnesia 的使用有更深層次的理解；
- ranch 的使用；
- erlang 控制腳本的編寫；
- libevent 的使用；
- 自定義協議的設計；
- 經過 gdb 排查問題；
-=-=-=-=-=- 我是胡歌腦殘粉的分隔線 -=-=-=-=-=-=-網絡
libupu 問題排查整理（最難查的一個）
今天終於查出了 libupu 常常會把 CPU 跑到 100% 的緣由了。該問題在各類環境中反覆出現過不下 10 次，但測試部門只彙報有問題出現，沒有安排測試人員配合復現過該問題（不知道是否測試部門太忙？仍是對組件的東西不夠重視？具個人觀察，很大一部分緣由是，組件不方便單獨進行測試，針對組件庫來講，問題尤爲嚴重），而等到與業務集成後的系統測試階段，測試部門的注意力又不會集中在組件問題上，只有出了問題後，纔會想起某某是責任人，派人過去叫你查，查的時候還不忘補一句"我今天還有一大堆業務功能要測，你趕快排查下，不行我先恢復環境測其它業務了"。好吧，開發組件的都不是親孃生的，仍是面對現實吧。
現實是這樣的，組件開發和維護人員，要能在業務未集成前，自行設計針對各類場景的模擬，要能根據業務運行時出問題的狀況，尋求復現的方法。緣由已經說過，沒人陪你玩，只能提升本身玩的水平。另外，組件提供給業務使用時，必定要把各類注意事項說清楚，最好白紙黑字寫清楚，尤爲是否容許跨線程使用啊，鎖問題啊，回調數據定義和擴展性啊，等等。不然，任由業務自行發揮，後面可就慘了，甚至殘了。
廢話囉嗦了這麼多，下面進入正題。
問題出現時的表現以下（逐層深刻的說明）：數據結構
- 某線程 CPU 跑到接近 100% （使用 libupu 庫的線程）
- 死循環發生在用戶態調用中（libevent 庫內部）
- 經過 gdb 發現，發生問題時，定時器小根堆頂的事件狀態值存在問題（ev_flags）
因爲最初不知道復現問題的方法，因此只能在發生問題後，再經過 gdb 抓取 core 文件進行分析，而此時只能對結果進行分析判斷，沒法知道程序從正常運行是如何轉變成死循環的。這種類型的問題和分析程序崩潰的 core 文件仍是不太同樣的（我的結論）。
排查問題時遇到的現實問題：架構
- 多種業務使用同一動態庫，每種業務打包相關文件時會將使用的庫全打進去，但庫的版本有不一致的狀況；
- 業務引用動態庫的路徑各有不一樣，各業務之間存在交叉引用動態庫的狀況，致使更新庫文件的時候可能對其餘業務形成影響；
- 線上環境中的庫均爲 release 版本，且不是經過剔除 debug 版本符號生成的，故如何正確加載符號也是個小技術點；
在解決了上述問題後，就能夠真正分析該問題的狀況了。
（下面的跟蹤是在可以復現問題的狀況下進行的）app
[root@upu_1 pas]#
[root@upu_1 pas]# strace -t -s 1024 -p 30732
Process 30732 attached - interrupt to quit
[ Process PID=30732 runs in 32 bit mode. ]
13:59:59 clock_gettime(CLOCK_MONOTONIC, {152346, 824968959}) = 0
13:59:59 gettimeofday({1445666399, 416615}, NULL) = 0
13:59:59 epoll_wait(26, {{EPOLLIN, {u32=29, u64=29}}}, 32, 9120) = 1
14:00:08 clock_gettime(CLOCK_MONOTONIC, {152355, 726754428}) = 0
14:00:08 gettimeofday({1445666408, 318367}, NULL) = 0
14:00:08 read(29, "\0", 1024) = 1
14:00:08 read(29, 0x57bffdac, 1024) = -1 EAGAIN (Resource temporarily unavailable)
在 bufferevent-pair 的讀端發現 137 字節數據，說明有業務調用了數據發送接口
14:00:08 time(NULL) = 1445666408
14:00:08 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:08 write(2, "[libupu][14:00:08]: handle_bussiness_data() => evbuffer_get_length(pair[1]->input) = 137\n", 89) = 89
修正 fd 31 關注可讀可寫事件
14:00:08 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN|EPOLLOUT, {u32=31, u64=31}}) = 0
將 137 字節數據從 bufferevent-pair 中搬移到網絡發送用的 bufferevent 中
14:00:08 time(NULL) = 1445666408
14:00:08 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) =
14:00:08 write(2, "[libupu][14:00:08]: handle_bussiness_data() => evbuffer_remove_buffer, move 137 Bytes from pair[1]->input to m_pBufferEvent->output\n", 132) = 132
等待可寫事件，觸發後，發送該 137 字節數據
14:00:08 epoll_wait(26, {{EPOLLOUT, {u32=31, u64=31}}}, 32, 218) = 1
14:00:08 clock_gettime(CLOCK_MONOTONIC, {152355, 727937926}) = 0
14:00:08 gettimeofday({1445666408, 320427}, NULL) = 0
14:00:08 writev(31, [{"\0224Vx\0\0\0\4\0\0\0\23\0\0\0y", 16}, {"{\"callnum\": 0, \"devid\": \"\", \"userdomain\": \"0q0y1aphxubof8ycru6fsgsk\", \"outcallnum\": 0, \"phonecallnum\": 0, \"incallnum\": 0}", 121}], 2) = 137
修正 fd 31 關注可讀事件
14:00:08 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
等待可讀事件，觸發後
14:00:08 epoll_wait(26, {{EPOLLIN, {u32=31, u64=31}}}, 32, 217) = 1
14:00:08 clock_gettime(CLOCK_MONOTONIC, {152355, 730703966}) = 0
14:00:08 gettimeofday({1445666408, 322313}, NULL) = 0
發現 socket 緩衝區中有 16 字節可讀數據，讀取 16 字節數據
14:00:08 ioctl(31, FIONREAD, [16]) = 0
14:00:08 readv(31, [{"\0224Vx\0\0\0\4\0\0\0\0\0\0\0\0", 16}], 1) = 16
修正 fd 31 再也不關注事件（由於不是 EV_PERSIST 類型，因此內部會自動刪除）
14:00:08 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
將收到的應答信息回調給業務
14:00:08 time(NULL) = 1445666408
14:00:08 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:08 write(2, "[libupu][14:00:08]: handle_upu_response() => ### enter CallBack ### [RESULT] nRspType(0)\n", 90) = 90
14:00:08 gettimeofday({1445666408, 323146}, NULL) = 0
14:00:08 write(6, "\220\6PY", 4) = 4
14:00:08 send(18, "\3\356\0\0\0\7\0\0\0\0\0\211\0\0\0\0\5\0\207!\350\330\350\0\7\4\335\2[pid]:25002 [UpuWrapper]: [UpuMsgCallBack] recive upu callback msg(3),resultType:0, nResultCount:0, arg point:0x94f4870 \n", 153, 0) = 153
14:00:08 gettimeofday({1445666408, 323701}, NULL) = 0
14:00:08 write(6, "x\4\340V", 4) = 4
14:00:08 send(18, "\3\356\0\0\0\7\0\0\0\0\0\221\0\0\0\0\5\0\217!\350\330\350\0\7\4\335\3[pid]:25002 [UpuWrapper]: [UpuClientMsgCallBack] ClientSeesion:0x94f50f8 recive upu result msg:3, result type:0, nResultCount:0 \n", 161, 0) = 161
14:00:08 futex(0x94f48cc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x94f48c8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
14:00:08 futex(0x94f48f8, FUTEX_WAKE_PRIVATE, 1) = 1
14:00:08 futex(0x94f4924, FUTEX_WAIT_PRIVATE, 125, NULL) = 0
14:00:08 futex(0x94f4950, FUTEX_WAKE_PRIVATE, 1) = 0
修正 fd 31 關注可讀事件（添加）
14:00:08 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
等待可讀事件（此處針對的是 fd 29 和以前不一樣）
14:00:08 epoll_wait(26, {{EPOLLIN, {u32=29, u64=29}}}, 32, 10000) = 1
14:00:08 clock_gettime(CLOCK_MONOTONIC, {152356, 8231631}) = 0
14:00:08 gettimeofday({1445666408, 599857}, NULL) = 0
14:00:08 read(29, "\0", 1024) = 1
14:00:08 read(29, 0x57bffdac, 1024) = -1 EAGAIN (Resource temporarily unavailable)
---- 新一輪數據處理 ----
在 bufferevent-pair 的讀端發現 192 字節數據，說明有業務調用了發送接口
14:00:08 time(NULL) = 1445666408
14:00:08 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:08 write(2, "[libupu][14:00:08]: handle_bussiness_data() => evbuffer_get_length(pair[1]->input) = 192\n", 89) = 89
14:00:08 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN|EPOLLOUT, {u32=31, u64=31}}) = 0
14:00:08 time(NULL) = 1445666408
14:00:08 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:08 write(2, "[libupu][14:00:08]: handle_bussiness_data() => evbuffer_remove_buffer, move 192 Bytes from pair[1]->input to m_pBufferEvent->output\n", 132) = 132
14:00:08 epoll_wait(26, {{EPOLLOUT, {u32=31, u64=31}}}, 32, 9723) = 1
14:00:08 clock_gettime(CLOCK_MONOTONIC, {152356, 9572196}) = 0
14:00:08 gettimeofday({1445666408, 601149}, NULL) = 0
14:00:08 writev(31, [{"\0224Vx\0\0\0\3\0\0\0\f\0\0\0\260", 16}, {"{\"callnum\": 2, \"devid\": \"10103000000002000000000000000002\", \"platformid\": \"6f9bde0c-c069-4af3-946c-78b3a4191bfe\", \"nuaddr\": \"5pys5ZywIzE6MTcyLjE2LjE4NS4xMzUA\", \"nudefroute\": 1}", 176}], 2) = 192
14:00:08 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:08 epoll_wait(26, {{EPOLLIN, {u32=31, u64=31}}}, 32, 9722) = 1
14:00:08 clock_gettime(CLOCK_MONOTONIC, {152356, 11685126}) = 0
14:00:08 gettimeofday({1445666408, 603291}, NULL) = 0
14:00:08 ioctl(31, FIONREAD, [16]) = 0
14:00:08 readv(31, [{"\0224Vx\0\0\0\3\0\0\0\0\0\0\0\0", 16}], 1) = 16
14:00:08 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:08 time(NULL) = 1445666408
14:00:08 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:08 write(2, "[libupu][14:00:08]: handle_upu_response() => ### enter CallBack ### [RESULT] nRspType(0)\n", 90) = 90
14:00:08 gettimeofday({1445666408, 604082}, NULL) = 0
14:00:08 write(6, "\220\6PY", 4) = 4
14:00:08 send(18, "\3\356\0\0\0\7\0\0\0\0\0\211\0\0\0\0\5\0\207!\350\330\350\0\7\4\335\2[pid]:25002 [UpuWrapper]: [UpuMsgCallBack] recive upu callback msg(3),resultType:0, nResultCount:0, arg point:0x94f4870 \n", 153, 0) = 153
14:00:08 gettimeofday({1445666408, 604443}, NULL) = 0
14:00:08 write(6, "x\4\340V", 4) = 4
14:00:08 send(18, "\3\356\0\0\0\7\0\0\0\0\0\221\0\0\0\0\5\0\217!\350\330\350\0\7\4\335\3[pid]:25002 [UpuWrapper]: [UpuClientMsgCallBack] ClientSeesion:0x94f50f8 recive upu result msg:3, result type:0, nResultCount:0 \n", 161, 0) = 161
14:00:08 futex(0x94f48cc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x94f48c8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
14:00:08 futex(0x94f48f8, FUTEX_WAKE_PRIVATE, 1) = 1
14:00:08 futex(0x94f4924, FUTEX_WAIT_PRIVATE, 127, NULL) = -1 EAGAIN (Resource temporarily unavailable)
14:00:08 futex(0x94f4950, FUTEX_WAKE_PRIVATE, 1) = 0
14:00:08 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
---- 新一輪數據處理 ----
這裏出現了 10s 的空等 -- 由於在 10s 內沒有可讀事件觸發
14:00:08 epoll_wait(26, {}, 32, 10000) = 0
14:00:18 clock_gettime(CLOCK_MONOTONIC, {152366, 23210960}) = 0
14:00:18 gettimeofday({1445666418, 614827}, NULL) = 0
這裏進行一系列修改，對應代碼哪裏？
14:00:18 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:18 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:18 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:18 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLOUT, {u32=31, u64=31}}) = 0
14:00:18 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN|EPOLLOUT, {u32=31, u64=31}}) = 0
等待可寫事件，觸發後，發送心跳請求
14:00:18 epoll_wait(26, {{EPOLLOUT, {u32=31, u64=31}}}, 32, 10000) = 1
14:00:18 clock_gettime(CLOCK_MONOTONIC, {152366, 24061012}) = 0
14:00:18 gettimeofday({1445666418, 615704}, NULL) = 0
14:00:18 writev(31, [{"\0224Vx\0\0\0\0\0\0\0\2\0\0\0\0", 16}], 1) = 16
等待可讀事件，觸發後，讀取心跳應答
14:00:18 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:18 epoll_wait(26, {{EPOLLIN, {u32=31, u64=31}}}, 32, 10000) = 1
14:00:18 clock_gettime(CLOCK_MONOTONIC, {152366, 25500295}) = 0
14:00:18 gettimeofday({1445666418, 617107}, NULL) = 0
14:00:18 ioctl(31, FIONREAD, [16]) = 0
14:00:18 readv(31, [{"\0224Vx\0\0\0\0\0\0\0\3\0\0\0\0", 16}], 1) = 16
這裏對應了回調函數中針對數據 body 爲 0 狀況的處理（什麼動做都沒有進行，僅在函數入口和出口處對事件進行了處理）
14:00:18 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:18 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
又等了 10s 沒有數據可讀
14:00:18 epoll_wait(26, {}, 32, 10000) = 0
14:00:28 clock_gettime(CLOCK_MONOTONIC, {152376, 36211523}) = 0
14:00:28 gettimeofday({1445666428, 627827}, NULL) = 0
14:00:28 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:28 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:28 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:28 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLOUT, {u32=31, u64=31}}) = 0
14:00:28 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN|EPOLLOUT, {u32=31, u64=31}}) = 0
等待可寫事件，觸發後，發送心跳請求
14:00:28 epoll_wait(26, {{EPOLLOUT, {u32=31, u64=31}}}, 32, 10000) = 1
14:00:28 clock_gettime(CLOCK_MONOTONIC, {152376, 37039083}) = 0
14:00:28 gettimeofday({1445666428, 628705}, NULL) = 0
14:00:28 writev(31, [{"\0224Vx\0\0\0\0\0\0\0\2\0\0\0\0", 16}], 1) = 16
等待可讀事件，觸發後，讀取心跳應答
14:00:28 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:28 epoll_wait(26, {{EPOLLIN, {u32=31, u64=31}}}, 32, 10000) = 1
14:00:28 clock_gettime(CLOCK_MONOTONIC, {152376, 37828723}) = 0
14:00:28 gettimeofday({1445666428, 629429}, NULL) = 0
14:00:28 ioctl(31, FIONREAD, [16]) = 0
14:00:28 readv(31, [{"\0224Vx\0\0\0\0\0\0\0\3\0\0\0\0", 16}], 1) = 16
14:00:28 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:28 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
等待可讀事件（此處針對的是 fd 29）
14:00:28 epoll_wait(26, {{EPOLLIN, {u32=29, u64=29}}}, 32, 10000) = 1
14:00:38 clock_gettime(CLOCK_MONOTONIC, {152385, 814250349}) = 0
14:00:38 gettimeofday({1445666438, 405878}, NULL) = 0
14:00:38 read(29, "\0", 1024) = 1
14:00:38 read(29, 0x57bffdac, 1024) = -1 EAGAIN (Resource temporarily unavailable)
---- 新一輪數據處理 ----
14:00:38 time(NULL) = 1445666438
14:00:38 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:38 write(2, "[libupu][14:00:38]: handle_bussiness_data() => evbuffer_get_length(pair[1]->input) = 137\n", 89) = 89
14:00:38 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN|EPOLLOUT, {u32=31, u64=31}}) = 0
14:00:38 time(NULL) = 1445666438
14:00:38 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:38 write(2, "[libupu][14:00:38]: handle_bussiness_data() => evbuffer_remove_buffer, move 137 Bytes from pair[1]->input to m_pBufferEvent->output\n", 132) = 132
14:00:38 epoll_wait(26, {{EPOLLOUT, {u32=31, u64=31}}}, 32, 224) = 1
14:00:38 clock_gettime(CLOCK_MONOTONIC, {152385, 816366473}) = 0
14:00:38 gettimeofday({1445666438, 407970}, NULL) = 0
14:00:38 writev(31, [{"\0224Vx\0\0\0\4\0\0\0\23\0\0\0y", 16}, {"{\"callnum\": 0, \"devid\": \"\", \"userdomain\": \"0q0y1aphxubof8ycru6fsgsk\", \"outcallnum\": 0, \"phonecallnum\": 0, \"incallnum\": 0}", 121}], 2) = 137
14:00:38 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:38 epoll_wait(26, {{EPOLLIN, {u32=31, u64=31}}}, 32, 222) = 1
14:00:38 clock_gettime(CLOCK_MONOTONIC, {152385, 817856690}) = 0
14:00:38 gettimeofday({1445666438, 409460}, NULL) = 0
14:00:38 ioctl(31, FIONREAD, [16]) = 0
14:00:38 readv(31, [{"\0224Vx\0\0\0\4\0\0\0\0\0\0\0\0", 16}], 1) = 16
14:00:38 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:38 time(NULL) = 1445666438
14:00:38 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:38 write(2, "[libupu][14:00:38]: handle_upu_response() => ### enter CallBack ### [RESULT] nRspType(0)\n", 90) = 90
14:00:38 gettimeofday({1445666438, 410275}, NULL) = 0
14:00:38 write(6, "\340\4\220Y", 4) = 4
14:00:38 send(18, "\3\356\0\0\0\7\0\0\0\0\0\211\0\0\0\0\5\0\207!\350\331\6\0\7\4\335\2[pid]:25002 [UpuWrapper]: [UpuMsgCallBack] recive upu callback msg(3),resultType:0, nResultCount:0, arg point:0x94f4870 \n", 153, 0) = 153
14:00:38 gettimeofday({1445666438, 410812}, NULL) = 0
14:00:38 write(6, "x\4\340V", 4) = 4
14:00:38 send(18, "\3\356\0\0\0\7\0\0\0\0\0\221\0\0\0\0\5\0\217!\350\331\6\0\7\4\335\3[pid]:25002 [UpuWrapper]: [UpuClientMsgCallBack] ClientSeesion:0x94f50f8 recive upu result msg:3, result type:0, nResultCount:0 \n", 161, 0) = 161
14:00:38 futex(0x94f48cc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x94f48c8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
14:00:38 futex(0x94f48f8, FUTEX_WAKE_PRIVATE, 1) = 1
14:00:38 futex(0x94f4924, FUTEX_WAIT_PRIVATE, 129, NULL) = 0
14:00:38 futex(0x94f4950, FUTEX_WAKE_PRIVATE, 1) = 0
14:00:38 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:38 epoll_wait(26, {{EPOLLIN, {u32=29, u64=29}}}, 32, 10000) = 1
14:00:38 clock_gettime(CLOCK_MONOTONIC, {152386, 116071089}) = 0
14:00:38 gettimeofday({1445666438, 707688}, NULL) = 0
14:00:38 read(29, "\0", 1024) = 1
14:00:38 read(29, 0x57bffdac, 1024) = -1 EAGAIN (Resource temporarily unavailable)
---- 新一輪數據處理 ----
14:00:38 time(NULL) = 1445666438
14:00:38 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:38 write(2, "[libupu][14:00:38]: handle_bussiness_data() => evbuffer_get_length(pair[1]->input) = 192\n", 89) = 89
14:00:38 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN|EPOLLOUT, {u32=31, u64=31}}) = 0
14:00:38 time(NULL) = 1445666438
14:00:38 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:38 write(2, "[libupu][14:00:38]: handle_bussiness_data() => evbuffer_remove_buffer, move 192 Bytes from pair[1]->input to m_pBufferEvent->output\n", 132) = 132
14:00:38 epoll_wait(26, {{EPOLLOUT, {u32=31, u64=31}}}, 32, 9702) = 1
14:00:38 clock_gettime(CLOCK_MONOTONIC, {152386, 119894680}) = 0
14:00:38 gettimeofday({1445666438, 711499}, NULL) = 0
14:00:38 writev(31, [{"\0224Vx\0\0\0\3\0\0\0\f\0\0\0\260", 16}, {"{\"callnum\": 2, \"devid\": \"10103000000002000000000000000002\", \"platformid\": \"6f9bde0c-c069-4af3-946c-78b3a4191bfe\", \"nuaddr\": \"5pys5ZywIzE6MTcyLjE2LjE4NS4xMzUA\", \"nudefroute\": 1}", 176}], 2) = 192
14:00:38 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:38 epoll_wait(26, {{EPOLLIN, {u32=31, u64=31}}}, 32, 9698) = 1
14:00:38 clock_gettime(CLOCK_MONOTONIC, {152386, 122371397}) = 0
14:00:38 gettimeofday({1445666438, 713982}, NULL) = 0
14:00:38 ioctl(31, FIONREAD, [16]) = 0
14:00:38 readv(31, [{"\0224Vx\0\0\0\3\0\0\0\0\0\0\0\0", 16}], 1) = 16
14:00:38 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:38 time(NULL) = 1445666438
14:00:38 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:38 write(2, "[libupu][14:00:38]: handle_upu_response() => ### enter CallBack ### [RESULT] nRspType(0)\n", 90) = 90
14:00:38 gettimeofday({1445666438, 714792}, NULL) = 0
14:00:38 write(6, "\340\4\220Y", 4) = 4
14:00:38 send(18, "\3\356\0\0\0\7\0\0\0\0\0\211\0\0\0\0\5\0\207!\350\331\6\0\7\4\335\2[pid]:25002 [UpuWrapper]: [UpuMsgCallBack] recive upu callback msg(3),resultType:0, nResultCount:0, arg point:0x94f4870 \n", 153, 0) = 153
14:00:38 gettimeofday({1445666438, 715315}, NULL) = 0
14:00:38 write(6, "x\4\340V", 4) = 4
14:00:38 send(18, "\3\356\0\0\0\7\0\0\0\0\0\221\0\0\0\0\5\0\217!\350\331\6\0\7\4\335\3[pid]:25002 [UpuWrapper]: [UpuClientMsgCallBack] ClientSeesion:0x94f50f8 recive upu result msg:3, result type:0, nResultCount:0 \n", 161, 0) = 161
14:00:38 futex(0x94f48cc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x94f48c8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
14:00:38 futex(0x94f48f8, FUTEX_WAKE_PRIVATE, 1) = 1
等待可讀事件，觸發後
14:00:38 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:38 epoll_wait(26, {{EPOLLIN, {u32=31, u64=31}}}, 32, 10000) = 1
14:00:43 clock_gettime(CLOCK_MONOTONIC, {152390, 497764210}) = 0
14:00:43 gettimeofday({1445666443, 89440}, NULL) = 0
發現此時 socket 中可讀數據爲 0 （此時人爲將服務器進程中止）
14:00:43 ioctl(31, FIONREAD, [0]) = 0
讀出一些亂七八糟的數據（應該是因爲 readv 使用的保存讀取結果的 buffer 沒有清空的緣故）
14:00:43 readv(31, [{"[pid]:25002 [UpuWrapper]: [UpuClientMsgCallBack] ClientSeesion:0x94f50f8 recive upu result msg:3, result type:0, nResultCount:0 \n\0\2\0@\0\320W\371\10\2\0@\0\320W@\0\320Wdows\",\"status\":\"callidle\",\"nuaddr\":\"172.16.185.135\",\"mtaddr\":\"172.16.72.105\",\"userdomain\":\"0q0y1aphxubof8ycru6fsgsk\",\"devid\":\"10103000000002000000000000000002\",\"data\":\"\"}]\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\10\2\0\0\231\7\2\0\0\0\0\0/localtime\0\0\10\2\0\0\201\7\2\0\0\0\0\0domain\00005\0\0\0 \2\0\0$\0\0\0008\f\320W\0\0\0\0\10\0\0\0\1\0\0\0\300\10\320W\0\0\0\0@\2\0\0,\0\0\0\340\10\320W\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0h\2\0\0,\0\0\0\350\f\320W\0\0\0\0\n\0\0\0h\v\320W\1\0\0\0D\f\320W4\v\320W\n\0\0\0\220\2\0\0004\0\0\0\270\t\320W4\v\320W\344\n\320W\344\n\320W|\n\320W4\n\320WT\t\320WT\t\320W\374\10\320W\374\10\320W\0\0\0\0\201\0\0\0@\0\320W@\0\320W\20\0\0\0,\0\0\0\260\f\320W4\n\320W\204\f\320W\250\n\320W\2\0\0\0prototype\0001\0\0\0\0\0I\0\0\0\200\0\320W\200\0\320W0000002000000000000000002\"\0ff\"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0@\3\0\0004\0\0\0\0\0\0\0c52a-deb2-499c-add5-db70f1f62bff\0\0\0\0\0\0\0\0\31\6\2\0@\0\320Wx\6\320W\20\0\0\0004\0\0\0\10\t\320Wc52a-deb2-499c-add5-db70f1f62bff\0\0\0\0\0\0\0\0\331\5\2\0x\6\320W8\t\320W\0\0\0\0\0\0\0\0\0\0\0\0moid\0\0\0\0)\0\0\0H\v\320Wx\6\320W\20\0\0\0\34\0\0\0\200\10\320W110000423\0\0\0H\0\0\0$\0\0\0(\v\320W4\v\320W"..., 4096}], 1) = 0
14:00:43 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
此時回調函數中能夠讀到 BEV_EVENT_EOF | BEV_EVENT_READING ，errno 爲 11 即 EAGAIN
14:00:43 time(NULL) = 1445666443
14:00:43 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:43 write(2, "[libupu][14:00:43]: handle_event() => sEvent(17), recv UPU disconnect(eof), errno:11 error:'Resource temporarily unavailable'\n", 127) = 127
發現代碼中存在以下處理邏輯，斷定若 errno 爲 EAGAIN 則直接 return 。能夠看出此時返回，將不會關閉 fd 31 。更進入一步，該邏輯致使沒有釋放網絡通信所使用的 bufferevent 。
--
if ( EAGAIN == errno )
{
// libevent will sometimes recv again when it's not actually ready,
// this results in a 0 return value, and errno will be set to EAGAIN(try again).
// This does not mean there is a hard socket error, but simple needs to be read again
return ;
}
--
從回調中返回後，代碼會從 event_base_dispatch 中退出，由於當前 base 中已經沒有其餘事件了
可是，須要注意的是，此時在業務結構中包含了 libevent 相關內容並無進行清理操做，若後續直接被使用，應該會致使問題
14:00:43 time(NULL) = 1445666443
14:00:43 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:43 write(2, "[libupu][14:00:43]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
14:00:43 gettimeofday({1445666443, 91211}, NULL) = 0
14:00:43 write(6, "\340\4\220Y", 4) = 4
14:00:43 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\331\v\0\7\4\335\2[pid]:25002 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94f50f8\n", 126, 0) = 126
業務代碼主動掛起 4s
14:00:43 nanosleep({4, 0}, NULL) = 0
對應業務層的處理邏輯以下（這種處理我的以爲很不合理）
--
// 進入線程循環
while( !ptTaskParm->IsTerminal() )
{
ThreadLoop(ptTaskParm);
if (!ptTaskParm->IsTerminal())
{
OspDelay(4*1000);
}
}
--
---- 新建鏈接處理 ----
4s 掛起後，在業務層從新創建 TCP 鏈接（注意，不是庫內部重連），能夠看到，這裏直接就使用了 fd 13 ，本次 connect 調用成功
緣由就是由於底層沒有對 fd 13 進行關閉，重用了以前的 bufferevent 致使
14:00:47 clock_gettime(CLOCK_MONOTONIC, {152394, 500384617}) = 0
14:00:47 gettimeofday({1445666447, 92001}, NULL) = 0
14:00:47 connect(31, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = 0
修正 fd 31 關注可寫事件（添加）
14:00:47 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLOUT, {u32=31, u64=31}}) = 0
14:00:47 time(NULL) = 1445666447
14:00:47 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:47 write(2, "[libupu][14:00:47]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
14:00:47 gettimeofday({1445666447, 92824}, NULL) = 0
14:00:47 write(6, "\340\4\220Y", 4) = 4
14:00:47 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\331\17\0\7\4\335\2[pid]:25002 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94f50f8 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
從新進入 event_base_dispatch 事件循環邏輯
14:00:47 time(NULL) = 1445666447
14:00:47 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:47 write(2, "[libupu][14:00:47]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
等待可寫事件，觸發後
14:00:47 clock_gettime(CLOCK_MONOTONIC, {152394, 502191015}) = 0
14:00:47 gettimeofday({1445666447, 93795}, NULL) = 0
14:00:47 epoll_wait(26, {{EPOLLOUT, {u32=31, u64=31}}}, 32, 0) = 1
14:00:47 clock_gettime(CLOCK_MONOTONIC, {152394, 502472418}) = 0
14:00:47 gettimeofday({1445666447, 94077}, NULL) = 0
斷定 TCP 鏈接是否出錯，此時沒有錯誤發生，認爲鏈接成功
14:00:47 getsockopt(31, SOL_SOCKET, SO_ERROR, [6231809014611574784], [4]) = 0
14:00:47 time(NULL) = 1445666447
14:00:47 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:47 write(2, "[libupu][14:00:47]: handle_event() => sEvent(128), UPU connect Success! enter Connected state.\n", 95) = 95
回調業務層告知鏈接成功
14:00:47 time(NULL) = 1445666447
14:00:47 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:47 write(2, "[libupu][14:00:47]: handle_event() => ### enter CallBack ### [CONNECTED] nRspType(0)\n", 86) = 86
14:00:47 futex(0xda534c, FUTEX_WAKE_PRIVATE, 1) = 1
14:00:47 gettimeofday({1445666447, 95137}, NULL) = 0
14:00:47 write(6, "\340\4\220Y", 4) = 4
14:00:47 send(18, "\3\356\0\0\0\7\0\0\0\0\0\211\0\0\0\0\5\0\207!\350\331\17\0\7\4\335\2[pid]:25002 [UpuWrapper]: [UpuMsgCallBack] recive upu callback msg(1),resultType:0, nResultCount:0, arg point:0x94f4870 \n", 153, 0) = 153
14:00:47 gettimeofday({1445666447, 95648}, NULL) = 0
14:00:47 write(6, "\340\4\220Y", 4) = 4
14:00:47 send(18, "\3\356\0\0\0\7\0\0\0\0\0y\0\0\0\0\5\0w!\350\331\17\0\7\4\335\3[pid]:25002 [UpuWrapper]: [UpuClientMsgCallBack] ClientSeesion:0x94f50f8 recive upu connect succ msg(1) \n", 137, 0) = 137
設置讀超時定時器
14:00:47 time(NULL) = 1445666447
14:00:47 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:47 write(2, "[libupu][14:00:47]: handle_event() => set 10s READ timer for Heartbeat.\n", 72) = 72
修正 fd 31 關注可讀可寫事件
14:00:47 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN|EPOLLOUT, {u32=31, u64=31}}) = 0
等待可讀事件觸發，觸發後
14:00:47 epoll_ctl(26, EPOLL_CTL_MOD, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
14:00:47 epoll_wait(26, {{EPOLLIN, {u32=31, u64=31}}}, 32, 3) = 1
14:00:47 clock_gettime(CLOCK_MONOTONIC, {152394, 505306960}) = 0
14:00:47 gettimeofday({1445666447, 96911}, NULL) = 0
再次發現此時 socket 中可讀數據爲 0 （這回就是由於以前沒有關閉 fd 31 重用了以前 bufferevent 致使的了）
14:00:47 ioctl(31, FIONREAD, [0]) = 0
14:00:47 readv(31, [{"[pid]:25002 [UpuWrapper]: [UpuClientMsgCallBack] ClientSeesion:0x94f50f8 recive upu result msg:3, result type:0, nResultCount:0 \n\0\2\0@\0\320W\371\10\2\0@\0\320W@\0\320Wdows\",\"status\":\"callidle\",\"nuaddr\":\"172.16.185.135\",\"mtaddr\":\"172.16.72.105\",\"userdomain\":\"0q0y1aphxubof8ycru6fsgsk\",\"devid\":\"10103000000002000000000000000002\",\"data\":\"\"}]\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\10\2\0\0\231\7\2\0\0\0\0\0/localtime\0\0\10\2\0\0\201\7\2\0\0\0\0\0domain\00005\0\0\0 \2\0\0$\0\0\0008\f\320W\0\0\0\0\10\0\0\0\1\0\0\0\300\10\320W\0\0\0\0@\2\0\0,\0\0\0\340\10\320W\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0h\2\0\0,\0\0\0\350\f\320W\0\0\0\0\n\0\0\0h\v\320W\1\0\0\0D\f\320W4\v\320W\n\0\0\0\220\2\0\0004\0\0\0\270\t\320W4\v\320W\344\n\320W\344\n\320W|\n\320W4\n\320WT\t\320WT\t\320W\374\10\320W\374\10\320W\0\0\0\0\201\0\0\0@\0\320W@\0\320W\20\0\0\0,\0\0\0\260\f\320W4\n\320W\204\f\320W\250\n\320W\2\0\0\0prototype\0001\0\0\0\0\0I\0\0\0\200\0\320W\200\0\320W0000002000000000000000002\"\0ff\"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0@\3\0\0004\0\0\0\0\0\0\0c52a-deb2-499c-add5-db70f1f62bff\0\0\0\0\0\0\0\0\31\6\2\0@\0\320Wx\6\320W\20\0\0\0004\0\0\0\10\t\320Wc52a-deb2-499c-add5-db70f1f62bff\0\0\0\0\0\0\0\0\331\5\2\0x\6\320W8\t\320W\0\0\0\0\0\0\0\0\0\0\0\0moid\0\0\0\0)\0\0\0H\v\320Wx\6\320W\20\0\0\0\34\0\0\0\200\10\320W110000423\0\0\0H\0\0\0$\0\0\0(\v\320W4\v\320W"..., 4096}], 1) = 0
14:00:47 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLIN, {u32=31, u64=31}}) = 0
此時回調函數中一樣會讀到 BEV_EVENT_EOF | BEV_EVENT_READING ，errno 爲 11 即 EAGAIN
14:00:47 time(NULL) = 1445666447
14:00:47 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:47 write(2, "[libupu][14:00:47]: handle_event() => sEvent(17), recv UPU disconnect(eof), errno:11 error:'Resource temporarily unavailable'\n", 127) = 127
14:00:47 epoll_wait(26, {}, 32, 1) = 0
再次退出 event_base_dispatch 循環（沒有其餘事件了）
14:00:47 clock_gettime(CLOCK_MONOTONIC, {152394, 507930524}) = 0
14:00:47 gettimeofday({1445666447, 99538}, NULL) = 0
14:00:47 time(NULL) = 1445666447
14:00:47 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:47 write(2, "[libupu][14:00:47]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
14:00:47 gettimeofday({1445666447, 100023}, NULL) = 0
14:00:47 write(6, "\340\4\220Y", 4) = 4
14:00:47 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\331\17\0\7\4\335\2[pid]:25002 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94f50f8\n", 126, 0) = 126
業務再次掛起 4s
14:00:47 nanosleep({4, 0}, NULL) = 0
---- 新建鏈接處理 ----
再次使用 fd 31 進行鏈接，本次 connect 調用失敗，errno 爲 106 即 EISCONN ，表示在當前 fd 上已經有鏈接成功創建
14:00:51 clock_gettime(CLOCK_MONOTONIC, {152398, 509179805}) = 0
14:00:51 gettimeofday({1445666451, 100795}, NULL) = 0
14:00:51 connect(31, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EISCONN (Transport endpoint is already connected)
14:00:51 time(NULL) = 1445666451
14:00:51 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:51 write(2, "[libupu][14:00:51]: handle_event() => sEvent(32), connect UPU server failed, errno:106 error:'Transport endpoint is already connected'\n", 136) = 136
在鏈接出錯後，代碼中關閉 fd 31
14:00:51 close(31) = 0
回調業務，告知鏈接斷開，實際上是發生了錯誤
14:00:51 time(NULL) = 1445666451
14:00:51 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:51 write(2, "[libupu][14:00:51]: handle_event() => ### enter CallBack ### [DISCONNECT] nRspType(0)\n", 87) = 87
14:00:51 gettimeofday({1445666451, 101988}, NULL) = 0
14:00:51 write(6, "\340\4\220Y", 4) = 4
14:00:51 send(18, "\3\356\0\0\0\7\0\0\0\0\0\211\0\0\0\0\5\0\207!\350\331\23\0\7\4\335\2[pid]:25002 [UpuWrapper]: [UpuMsgCallBack] recive upu callback msg(2),resultType:0, nResultCount:0, arg point:0x94f4870 \n", 153, 0) = 153
14:00:51 gettimeofday({1445666451, 102459}, NULL) = 0
14:00:51 write(6, "\340\4\220Y", 4) = 4
14:00:51 send(18, "\3\356\0\0\0\7\0\0\0\0\0w\0\0\0\0\5\0u!\350\331\23\0\7\4\335\2[pid]:25002 [UpuWrapper]: [UpuClientMsgCallBack] ClientSeesion:0x94f50f8 recive upu disconnect msg(2) \n", 135, 0) = 135
14:00:51 futex(0x94f48cc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x94f48c8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
14:00:51 futex(0x94f48f8, FUTEX_WAKE_PRIVATE, 1) = 1
14:00:51 time(NULL) = 1445666451
14:00:51 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:51 write(2, "[libupu][14:00:51]: handle_event() => back to Initial state.\n", 61) = 61
14:00:51 time(NULL) = 1445666451
14:00:51 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:51 futex(0xda5a8c, FUTEX_WAKE_PRIVATE, 1) = 1
14:00:51 write(2, "[libupu][14:00:51]: connect_server() => bufferevent_socket_connect Failed! back to initial state.\n", 98) = 98
14:00:51 gettimeofday({1445666451, 103964}, NULL) = 0
14:00:51 write(6, "\340\4\220Y", 4) = 4
14:00:51 send(18, "\3\356\0\0\0\7\0\0\0\0\0\210\0\0\0\0\5\0\206!\350\331\23\0\7\4\335\2[pid]:25002 [UpuWrapper]: [ThreadLoop] upu_client_connect failed! ClientSeesion:0x94f50f8 IP:172.16.185.136, port:2100 \n", 152, 0) = 152
業務層再次掛起 4s
14:00:51 nanosleep({4, 0}, NULL) = 0
---- 新建鏈接處理 ----
14:00:55 clock_gettime(CLOCK_MONOTONIC, {152402, 513113075}) = 0
14:00:55 gettimeofday({1445666455, 104729}, NULL) = 0
新建 socket
14:00:55 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 31
14:00:55 fcntl64(31, F_GETFL) = 0x2 (flags O_RDWR)
14:00:55 fcntl64(31, F_SETFL, O_RDWR|O_NONBLOCK) = 0
重建 TCP 鏈接
14:00:55 connect(31, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
關注可寫事件，鏈接中
14:00:55 epoll_ctl(26, EPOLL_CTL_ADD, 31, {EPOLLOUT, {u32=31, u64=31}}) = 0
14:00:55 time(NULL) = 1445666455
14:00:55 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:55 write(2, "[libupu][14:00:55]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
14:00:55 gettimeofday({1445666455, 105813}, NULL) = 0
14:00:55 write(6, "\220\6PY", 4) = 4
14:00:55 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\331\27\0\7\4\335\2[pid]:25002 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94f50f8 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
14:00:55 time(NULL) = 1445666455
14:00:55 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:55 futex(0xda5a8c, FUTEX_WAKE_PRIVATE, 1) = 1
進入 event_base_dispatch 循環
14:00:55 write(2, "[libupu][14:00:55]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
14:00:55 futex(0xda534c, FUTEX_WAKE_PRIVATE, 1) = 1
14:00:55 clock_gettime(CLOCK_MONOTONIC, {152402, 515334124}) = 0
14:00:55 gettimeofday({1445666455, 106938}, NULL) = 0
斷定 TCP 建鏈過程是否有錯誤發生，發現錯誤（實際上是由於服務器還沒有啓動成功，鏈接被拒）
14:00:55 epoll_wait(26, {{EPOLLERR|EPOLLHUP, {u32=31, u64=31}}}, 32, 0) = 1
14:00:55 clock_gettime(CLOCK_MONOTONIC, {152402, 515614415}) = 0
14:00:55 gettimeofday({1445666455, 107217}, NULL) = 0
14:00:55 getsockopt(31, SOL_SOCKET, SO_ERROR, [6231809014611574895], [4]) = 0
發現錯誤，就直接刪除 fd 31 的可寫事件
14:00:55 epoll_ctl(26, EPOLL_CTL_DEL, 31, {EPOLLOUT, {u32=31, u64=31}}) = 0
鏈接被拒絕
14:00:55 time(NULL) = 1445666455
14:00:55 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:55 write(2, "[libupu][14:00:55]: handle_event() => sEvent(32), connect UPU server failed, errno:111 error:'Connection refused'\n", 115) = 115
關閉 fd 31
14:00:55 close(31) = 0
14:00:55 time(NULL) = 1445666455
14:00:55 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:55 write(2, "[libupu][14:00:55]: handle_event() => back to Initial state.\n", 61) = 61
此時剛好有業務調用，但願向服務器發送請求
但在回調處理中發現當前鏈接狀態不對，沒法進行業務處理
14:00:55 time(NULL) = 1445666455
14:00:55 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:55 write(2, "[libupu][14:00:55]: handle_bussiness_data() => Not Connected! m_nState(0) == UPU_INITIAL_STATE\n", 95) = 95
故直接丟棄當前請求數據
14:00:55 time(NULL) = 1445666455
14:00:55 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
14:00:55 write(2, "[libupu][14:00:55]: handle_bussiness_data() => evbuffer_drain 233 Bytes from pair[1]->input!\n", 93) = 93
14:00:55 epoll_wait(26, {}, 32, 3) = 0
14:00:55 clock_gettime(CLOCK_MONOTONIC, {152402, 520846158}) = 0
14:00:55 gettimeofday({1445666455, 112450}, NULL) = 0
執行到這裏，strace 的輸出卡住不動，CPU 進入 100% 狀態！
^CProcess 30732 detached
[root@upu_1 pas]#
此時剛好服務器進程啓動成功
[root@upu_1 pas]# ps aux|grep upu|grep beam
root 1140 153 0.1 1362136 39444 pts/1 Ssl+ 14:00 0:01 /opt/mcu/upu/erts-6.0/bin/beam.smp -K true -- -root /opt/mcu/upu -progname upu -- -home /opt/mcu/upu/erts-6.0/bin -- -boot /opt/mcu/upu/releases/1/upu -mode embedded -config /opt/mcu/upu/etc/upu.config -mnesia dir '/opt/mcu/upu/data' -sname upu@upu_1 -setcookie upu -- console
結果分析：運維
- 在最初發現服務器異常斷開時，沒有將相應的 socket 進行關閉，致使重連後，再次使用該 fd ，進而又遇到一次一樣的錯誤信息；
- 第二次重連時，發現當前 fd 上存在成功創建的鏈接，觸發錯誤處理邏輯，才關閉該 fd ；
- 第三次重連時，新建 socket fd ，並會遇到鏈接被拒的錯誤信息，當服務器啓動成功後，客戶端庫觸發用戶態死循環，說明在業務數據結構部分數據已經出現問題（小根堆頂出現沒法刪除的事件）。
知道問題緣由後，解決辦法就很簡單了， 去掉 EAGAIN 後就能夠了。修改後的輸出以下dom
[root@upu_1 pas]#
[root@upu_1 pas]# strace -t -s 1024 -p 7474
Process 7474 attached - interrupt to quit
[ Process PID=7474 runs in 32 bit mode. ]
16:22:40 clock_gettime(CLOCK_MONOTONIC, {160907, 560286547}) = 0
16:22:40 gettimeofday({1445674960, 151942}, NULL) = 0
16:22:40 epoll_wait(48,
{}, 32, 2016) = 0
16:22:42 clock_gettime(CLOCK_MONOTONIC, {160909, 578207925}) = 0
16:22:42 gettimeofday({1445674962, 169824}, NULL) = 0
16:22:42 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:42 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:42 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:42 time(NULL) = 1445674962
16:22:42 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:22:42 write(2, "[libupu][16:22:42]: handle_event() => sEvent(65), Heartbeat timeout 0 times.\n", 77) = 77
16:22:42 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLOUT, {u32=59, u64=59}}) = 0
16:22:42 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN|EPOLLOUT, {u32=59, u64=59}}) = 0
16:22:42 epoll_wait(48, {{EPOLLOUT, {u32=59, u64=59}}}, 32, 10000) = 1
16:22:42 clock_gettime(CLOCK_MONOTONIC, {160909, 579617265}) = 0
16:22:42 gettimeofday({1445674962, 171237}, NULL) = 0
16:22:42 writev(59, [{"\0224Vx\0\0\0\0\0\0\0\2\0\0\0\0", 16}], 1) = 16
16:22:42 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:42 epoll_wait(48, {{EPOLLIN, {u32=59, u64=59}}}, 32, 9999) = 1
16:22:42 clock_gettime(CLOCK_MONOTONIC, {160909, 581192194}) = 0
16:22:42 gettimeofday({1445674962, 172802}, NULL) = 0
16:22:42 ioctl(59, FIONREAD, [16]) = 0
16:22:42 readv(59, [{"\0224Vx\0\0\0\0\0\0\0\3\0\0\0\0", 16}], 1) = 16
16:22:42 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:42 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:42 epoll_wait(48,
{}, 32, 10000) = 0
16:22:52 clock_gettime(CLOCK_MONOTONIC, {160919, 592222255}) = 0
16:22:52 gettimeofday({1445674972, 183847}, NULL) = 0
16:22:52 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:52 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:52 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:52 time(NULL) = 1445674972
16:22:52 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:22:52 write(2, "[libupu][16:22:52]: handle_event() => sEvent(65), Heartbeat timeout 0 times.\n", 77) = 77
16:22:52 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLOUT, {u32=59, u64=59}}) = 0
16:22:52 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN|EPOLLOUT, {u32=59, u64=59}}) = 0
16:22:52 epoll_wait(48, {{EPOLLOUT, {u32=59, u64=59}}}, 32, 10000) = 1
16:22:52 clock_gettime(CLOCK_MONOTONIC, {160919, 593696901}) = 0
16:22:52 gettimeofday({1445674972, 185309}, NULL) = 0
16:22:52 writev(59, [{"\0224Vx\0\0\0\0\0\0\0\2\0\0\0\0", 16}], 1) = 16
16:22:52 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:52 epoll_wait(48, {{EPOLLIN, {u32=59, u64=59}}}, 32, 9999) = 1
16:22:52 clock_gettime(CLOCK_MONOTONIC, {160919, 594473398}) = 0
16:22:52 gettimeofday({1445674972, 186085}, NULL) = 0
16:22:52 ioctl(59, FIONREAD, [16]) = 0
16:22:52 readv(59, [{"\0224Vx\0\0\0\0\0\0\0\3\0\0\0\0", 16}], 1) = 16
16:22:52 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:52 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:22:52 epoll_wait(48,
{}, 32, 10000) = 0
16:23:02 clock_gettime(CLOCK_MONOTONIC, {160929, 605196847}) = 0
16:23:02 gettimeofday({1445674982, 196807}, NULL) = 0
16:23:02 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:02 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:02 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:02 time(NULL) = 1445674982
16:23:02 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:02 write(2, "[libupu][16:23:02]: handle_event() => sEvent(65), Heartbeat timeout 0 times.\n", 77) = 77
16:23:02 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLOUT, {u32=59, u64=59}}) = 0
16:23:02 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN|EPOLLOUT, {u32=59, u64=59}}) = 0
16:23:02 epoll_wait(48, {{EPOLLOUT, {u32=59, u64=59}}}, 32, 10000) = 1
16:23:02 clock_gettime(CLOCK_MONOTONIC, {160929, 606349531}) = 0
16:23:02 gettimeofday({1445674982, 197945}, NULL) = 0
16:23:02 writev(59, [{"\0224Vx\0\0\0\0\0\0\0\2\0\0\0\0", 16}], 1) = 16
16:23:02 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:02 epoll_wait(48, {{EPOLLIN, {u32=59, u64=59}}}, 32, 9999) = 1
16:23:02 clock_gettime(CLOCK_MONOTONIC, {160929, 607145054}) = 0
16:23:02 gettimeofday({1445674982, 198745}, NULL) = 0
16:23:02 ioctl(59, FIONREAD, [16]) = 0
16:23:02 readv(59, [{"\0224Vx\0\0\0\0\0\0\0\3\0\0\0\0", 16}], 1) = 16
16:23:02 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:02 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:02 epoll_wait(48,
{{EPOLLIN, {u32=59, u64=59}}}, 32, 10000) = 1
16:23:05 clock_gettime(CLOCK_MONOTONIC, {160932, 979276748}) = 0
16:23:05 gettimeofday({1445674985, 570870}, NULL) = 0
16:23:05 ioctl(59, FIONREAD, [0]) = 0
16:23:05 readv(59, [{"\0224Vx\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\230\6\200Y\0224Vx\0\0\0\0\0\0\0\3\0\0\0\0MsgCallBack] ClientSeesion:0x94da028 recive upu connect succ msg(1) \n\0int:0x\21\t\2\000628 \n\0\2\0\0\0\0\0\1\t\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\36\0\0@\0\200Y@\0\200Y\0\0\0\0\0\0\0\0\0\0\0\0\201\7\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}], 1) = 0
16:23:05 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:05 time(NULL) = 1445674985
16:23:05 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:05 write(2, "[libupu][16:23:05]: handle_event() => sEvent(17), recv UPU disconnect(eof), errno:4 error:'Interrupted system call'\n", 117) = 117
16:23:05 close(59) = 0
16:23:05 time(NULL) = 1445674985
16:23:05 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:05 write(2, "[libupu][16:23:05]: handle_event() => ### enter CallBack ### [DISCONNECT] nRspType(0)\n", 87) = 87
16:23:05 gettimeofday({1445674985, 573024}, NULL) = 0
16:23:05 write(6, "\320\4\240V", 4) = 4
16:23:05 send(18, "\3\356\0\0\0\7\0\0\0\0\0\211\0\0\0\0\5\0\207!\350\372i\0\7\4\335\2[pid]:3713 [UpuWrapper]: [UpuMsgCallBack] recive upu callback msg(2),resultType:0, nResultCount:0, arg point:0x94d4628 \n", 153, 0) = 153
16:23:05 gettimeofday({1445674985, 573516}, NULL) = 0
16:23:05 write(6, "\320\4\240V", 4) = 4
16:23:05 send(18, "\3\356\0\0\0\7\0\0\0\0\0w\0\0\0\0\5\0u!\350\372i\0\7\4\335\2[pid]:3713 [UpuWrapper]: [UpuClientMsgCallBack] ClientSeesion:0x94da028 recive upu disconnect msg(2) \n", 135, 0) = 135
16:23:05 time(NULL) = 1445674985
16:23:05 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:05 write(2, "[libupu][16:23:05]: handle_event() => back to Initial state.\n", 61) = 61
16:23:05 time(NULL) = 1445674985
16:23:05 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:05 write(2, "[libupu][16:23:05]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
16:23:05 gettimeofday({1445674985, 574723}, NULL) = 0
16:23:05 write(6, "\320\4\240V", 4) = 4
16:23:05 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\372i\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94da028\n", 126, 0) = 126
16:23:05 nanosleep({4, 0},
NULL) = 0
16:23:09 clock_gettime(CLOCK_MONOTONIC, {160936, 983810668}) = 0
16:23:09 gettimeofday({1445674989, 575416}, NULL) = 0
16:23:09 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 39
16:23:09 fcntl64(39, F_GETFL) = 0x2 (flags O_RDWR)
16:23:09 fcntl64(39, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:23:09 connect(39, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:09 epoll_ctl(48, EPOLL_CTL_ADD, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:09 time(NULL) = 1445674989
16:23:09 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:09 write(2, "[libupu][16:23:09]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
16:23:09 gettimeofday({1445674989, 576481}, NULL) = 0
16:23:09 write(6, "\320\4\240V", 4) = 4
16:23:09 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\372m\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94da028 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
16:23:09 time(NULL) = 1445674989
16:23:09 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:09 write(2, "[libupu][16:23:09]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
16:23:09 clock_gettime(CLOCK_MONOTONIC, {160936, 985598386}) = 0
16:23:09 gettimeofday({1445674989, 577239}, NULL) = 0
16:23:09 clock_gettime(CLOCK_MONOTONIC, {160936, 985796661}) = 0
16:23:09 gettimeofday({1445674989, 577402}, NULL) = 0
16:23:09 epoll_wait(48, {{EPOLLERR|EPOLLHUP, {u32=39, u64=39}}}, 32, 4) = 1
16:23:09 clock_gettime(CLOCK_MONOTONIC, {160936, 986085528}) = 0
16:23:09 gettimeofday({1445674989, 577684}, NULL) = 0
16:23:09 getsockopt(39, SOL_SOCKET, SO_ERROR, [6222784223170789487], [4]) = 0
16:23:09 epoll_ctl(48, EPOLL_CTL_DEL, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:09 time(NULL) = 1445674989
16:23:09 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:09 write(2, "[libupu][16:23:09]: handle_event() => sEvent(32), connect UPU server failed, errno:111 error:'Connection refused'\n", 115) = 115
16:23:09 close(39) = 0
16:23:09 time(NULL) = 1445674989
16:23:09 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:09 futex(0xda5a8c, FUTEX_WAKE_PRIVATE, 1) = 1
16:23:09 write(2, "[libupu][16:23:09]: handle_event() => back to Initial state.\n", 61) = 61
16:23:09 futex(0xda534c, FUTEX_WAKE_PRIVATE, 1) = 1
16:23:09 epoll_wait(48, {}, 32, 3) = 0
16:23:09 clock_gettime(CLOCK_MONOTONIC, {160936, 990331850}) = 0
16:23:09 gettimeofday({1445674989, 581909}, NULL) = 0
16:23:09 time(NULL) = 1445674989
16:23:09 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:09 write(2, "[libupu][16:23:09]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
16:23:09 gettimeofday({1445674989, 582208}, NULL) = 0
16:23:09 write(6, "\260oM\t", 4) = 4
16:23:09 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\372m\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94da028\n", 126, 0) = 126
16:23:09 nanosleep({4, 0},
NULL) = 0
16:23:13 clock_gettime(CLOCK_MONOTONIC, {160940, 991197248}) = 0
16:23:13 gettimeofday({1445674993, 582822}, NULL) = 0
16:23:13 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 39
16:23:13 fcntl64(39, F_GETFL) = 0x2 (flags O_RDWR)
16:23:13 fcntl64(39, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:23:13 connect(39, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:13 epoll_ctl(48, EPOLL_CTL_ADD, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:13 time(NULL) = 1445674993
16:23:13 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:13 write(2, "[libupu][16:23:13]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
16:23:13 gettimeofday({1445674993, 583984}, NULL) = 0
16:23:13 write(6, "\320\4\240V", 4) = 4
16:23:13 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\372q\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94da028 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
16:23:13 time(NULL) = 1445674993
16:23:13 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:13 write(2, "[libupu][16:23:13]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
16:23:13 clock_gettime(CLOCK_MONOTONIC, {160940, 993432530}) = 0
16:23:13 gettimeofday({1445674993, 585019}, NULL) = 0
16:23:13 clock_gettime(CLOCK_MONOTONIC, {160940, 993575132}) = 0
16:23:13 gettimeofday({1445674993, 585172}, NULL) = 0
16:23:13 epoll_wait(48, {{EPOLLERR|EPOLLHUP, {u32=39, u64=39}}}, 32, 3) = 1
16:23:13 clock_gettime(CLOCK_MONOTONIC, {160940, 993818395}) = 0
16:23:13 gettimeofday({1445674993, 585406}, NULL) = 0
16:23:13 getsockopt(39, SOL_SOCKET, SO_ERROR, [6222784223170789487], [4]) = 0
16:23:13 epoll_ctl(48, EPOLL_CTL_DEL, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:13 time(NULL) = 1445674993
16:23:13 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:13 write(2, "[libupu][16:23:13]: handle_event() => sEvent(32), connect UPU server failed, errno:111 error:'Connection refused'\n", 115) = 115
16:23:13 close(39) = 0
16:23:13 time(NULL) = 1445674993
16:23:13 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:13 write(2, "[libupu][16:23:13]: handle_event() => back to Initial state.\n", 61) = 61
16:23:13 epoll_wait(48, {}, 32, 3) = 0
16:23:13 clock_gettime(CLOCK_MONOTONIC, {160940, 998060275}) = 0
16:23:13 gettimeofday({1445674993, 589658}, NULL) = 0
16:23:13 time(NULL) = 1445674993
16:23:13 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:13 write(2, "[libupu][16:23:13]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
16:23:13 gettimeofday({1445674993, 590058}, NULL) = 0
16:23:13 write(6, "\260oM\t", 4) = 4
16:23:13 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\372q\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94da028\n", 126, 0) = 126
16:23:13 nanosleep({4, 0},
NULL) = 0
16:23:17 clock_gettime(CLOCK_MONOTONIC, {160944, 999172495}) = 0
16:23:17 gettimeofday({1445674997, 590787}, NULL) = 0
16:23:17 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 39
16:23:17 fcntl64(39, F_GETFL) = 0x2 (flags O_RDWR)
16:23:17 fcntl64(39, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:23:17 connect(39, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:17 epoll_ctl(48, EPOLL_CTL_ADD, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:17 time(NULL) = 1445674997
16:23:17 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:17 write(2, "[libupu][16:23:17]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
16:23:17 gettimeofday({1445674997, 591935}, NULL) = 0
16:23:17 write(6, "\260oM\t", 4) = 4
16:23:17 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\372u\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94da028 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
16:23:17 time(NULL) = 1445674997
16:23:17 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:17 write(2, "[libupu][16:23:17]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
16:23:17 clock_gettime(CLOCK_MONOTONIC, {160945, 1277778}) = 0
16:23:17 gettimeofday({1445674997, 592883}, NULL) = 0
16:23:17 clock_gettime(CLOCK_MONOTONIC, {160945, 1458890}) = 0
16:23:17 gettimeofday({1445674997, 593063}, NULL) = 0
16:23:17 epoll_wait(48, {{EPOLLERR|EPOLLHUP, {u32=39, u64=39}}}, 32, 3) = 1
16:23:17 clock_gettime(CLOCK_MONOTONIC, {160945, 1747907}) = 0
16:23:17 gettimeofday({1445674997, 593352}, NULL) = 0
16:23:17 getsockopt(39, SOL_SOCKET, SO_ERROR, [6222784223170789487], [4]) = 0
16:23:17 epoll_ctl(48, EPOLL_CTL_DEL, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:17 time(NULL) = 1445674997
16:23:17 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:17 write(2, "[libupu][16:23:17]: handle_event() => sEvent(32), connect UPU server failed, errno:111 error:'Connection refused'\n", 115) = 115
16:23:17 close(39) = 0
16:23:17 time(NULL) = 1445674997
16:23:17 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:17 write(2, "[libupu][16:23:17]: handle_event() => back to Initial state.\n", 61) = 61
16:23:17 epoll_wait(48, {}, 32, 3) = 0
16:23:17 clock_gettime(CLOCK_MONOTONIC, {160945, 6224704}) = 0
16:23:17 gettimeofday({1445674997, 597831}, NULL) = 0
16:23:17 time(NULL) = 1445674997
16:23:17 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:17 write(2, "[libupu][16:23:17]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
16:23:17 gettimeofday({1445674997, 598290}, NULL) = 0
16:23:17 write(6, "\260oM\t", 4) = 4
16:23:17 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\372u\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94da028\n", 126, 0) = 126
16:23:17 nanosleep({4, 0},
NULL) = 0
16:23:21 clock_gettime(CLOCK_MONOTONIC, {160949, 7473367}) = 0
16:23:21 gettimeofday({1445675001, 599090}, NULL) = 0
16:23:21 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 39
16:23:21 fcntl64(39, F_GETFL) = 0x2 (flags O_RDWR)
16:23:21 fcntl64(39, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:23:21 connect(39, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:21 epoll_ctl(48, EPOLL_CTL_ADD, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:21 time(NULL) = 1445675001
16:23:21 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:21 write(2, "[libupu][16:23:21]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
16:23:21 gettimeofday({1445675001, 600265}, NULL) = 0
16:23:21 write(6, "\260oM\t", 4) = 4
16:23:21 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\372y\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94da028 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
16:23:21 time(NULL) = 1445675001
16:23:21 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:21 write(2, "[libupu][16:23:21]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
16:23:21 clock_gettime(CLOCK_MONOTONIC, {160949, 9690310}) = 0
16:23:21 gettimeofday({1445675001, 601298}, NULL) = 0
16:23:21 clock_gettime(CLOCK_MONOTONIC, {160949, 9875450}) = 0
16:23:21 gettimeofday({1445675001, 601506}, NULL) = 0
16:23:21 epoll_wait(48, {{EPOLLERR|EPOLLHUP, {u32=39, u64=39}}}, 32, 3) = 1
16:23:21 clock_gettime(CLOCK_MONOTONIC, {160949, 10229031}) = 0
16:23:21 gettimeofday({1445675001, 601836}, NULL) = 0
16:23:21 getsockopt(39, SOL_SOCKET, SO_ERROR, [6222784223170789487], [4]) = 0
16:23:21 epoll_ctl(48, EPOLL_CTL_DEL, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:21 time(NULL) = 1445675001
16:23:21 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:21 write(2, "[libupu][16:23:21]: handle_event() => sEvent(32), connect UPU server failed, errno:111 error:'Connection refused'\n", 115) = 115
16:23:21 close(39) = 0
16:23:21 time(NULL) = 1445675001
16:23:21 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:21 write(2, "[libupu][16:23:21]: handle_event() => back to Initial state.\n", 61) = 61
16:23:21 epoll_wait(48, {}, 32, 3) = 0
16:23:21 clock_gettime(CLOCK_MONOTONIC, {160949, 14762150}) = 0
16:23:21 gettimeofday({1445675001, 606383}, NULL) = 0
16:23:21 time(NULL) = 1445675001
16:23:21 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:21 write(2, "[libupu][16:23:21]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
16:23:21 gettimeofday({1445675001, 606918}, NULL) = 0
16:23:21 write(6, "\260oM\t", 4) = 4
16:23:21 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\372y\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94da028\n", 126, 0) = 126
16:23:21 nanosleep({4, 0},
NULL) = 0
16:23:25 clock_gettime(CLOCK_MONOTONIC, {160953, 16142873}) = 0
16:23:25 gettimeofday({1445675005, 607763}, NULL) = 0
16:23:25 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 39
16:23:25 fcntl64(39, F_GETFL) = 0x2 (flags O_RDWR)
16:23:25 fcntl64(39, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:23:25 connect(39, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:25 epoll_ctl(48, EPOLL_CTL_ADD, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:25 time(NULL) = 1445675005
16:23:25 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:25 write(2, "[libupu][16:23:25]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
16:23:25 gettimeofday({1445675005, 608919}, NULL) = 0
16:23:25 write(6, "\260oM\t", 4) = 4
16:23:25 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\372}\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94da028 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
16:23:25 time(NULL) = 1445675005
16:23:25 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:25 write(2, "[libupu][16:23:25]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
16:23:25 clock_gettime(CLOCK_MONOTONIC, {160953, 18286176}) = 0
16:23:25 gettimeofday({1445675005, 609895}, NULL) = 0
16:23:25 clock_gettime(CLOCK_MONOTONIC, {160953, 18472888}) = 0
16:23:25 gettimeofday({1445675005, 610078}, NULL) = 0
16:23:25 epoll_wait(48, {{EPOLLERR|EPOLLHUP, {u32=39, u64=39}}}, 32, 3) = 1
16:23:25 clock_gettime(CLOCK_MONOTONIC, {160953, 18760536}) = 0
16:23:25 gettimeofday({1445675005, 610366}, NULL) = 0
16:23:25 getsockopt(39, SOL_SOCKET, SO_ERROR, [6222784223170789487], [4]) = 0
16:23:25 epoll_ctl(48, EPOLL_CTL_DEL, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:25 time(NULL) = 1445675005
16:23:25 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:25 write(2, "[libupu][16:23:25]: handle_event() => sEvent(32), connect UPU server failed, errno:111 error:'Connection refused'\n", 115) = 115
16:23:25 close(39) = 0
16:23:25 time(NULL) = 1445675005
16:23:25 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:25 write(2, "[libupu][16:23:25]: handle_event() => back to Initial state.\n", 61) = 61
16:23:25 epoll_wait(48, {}, 32, 3) = 0
16:23:25 clock_gettime(CLOCK_MONOTONIC, {160953, 23241459}) = 0
16:23:25 gettimeofday({1445675005, 614850}, NULL) = 0
16:23:25 time(NULL) = 1445675005
16:23:25 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:25 write(2, "[libupu][16:23:25]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
16:23:25 gettimeofday({1445675005, 615333}, NULL) = 0
16:23:25 write(6, "\260oM\t", 4) = 4
16:23:25 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\372}\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94da028\n", 126, 0) = 126
16:23:25 nanosleep({4, 0},
NULL) = 0
16:23:29 clock_gettime(CLOCK_MONOTONIC, {160957, 24514610}) = 0
16:23:29 gettimeofday({1445675009, 616132}, NULL) = 0
16:23:29 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 39
16:23:29 fcntl64(39, F_GETFL) = 0x2 (flags O_RDWR)
16:23:29 fcntl64(39, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:23:29 connect(39, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:29 epoll_ctl(48, EPOLL_CTL_ADD, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:29 time(NULL) = 1445675009
16:23:29 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:29 write(2, "[libupu][16:23:29]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
16:23:29 gettimeofday({1445675009, 617295}, NULL) = 0
16:23:29 write(6, "\260oM\t", 4) = 4
16:23:29 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\372\201\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94da028 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
16:23:29 time(NULL) = 1445675009
16:23:29 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:29 write(2, "[libupu][16:23:29]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
16:23:29 clock_gettime(CLOCK_MONOTONIC, {160957, 26671985}) = 0
16:23:29 gettimeofday({1445675009, 618301}, NULL) = 0
16:23:29 clock_gettime(CLOCK_MONOTONIC, {160957, 26882105}) = 0
16:23:29 gettimeofday({1445675009, 618490}, NULL) = 0
16:23:29 epoll_wait(48, {{EPOLLERR|EPOLLHUP, {u32=39, u64=39}}}, 32, 3) = 1
16:23:29 clock_gettime(CLOCK_MONOTONIC, {160957, 27214855}) = 0
16:23:29 gettimeofday({1445675009, 618826}, NULL) = 0
16:23:29 getsockopt(39, SOL_SOCKET, SO_ERROR, [6222784223170789487], [4]) = 0
16:23:29 epoll_ctl(48, EPOLL_CTL_DEL, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:29 time(NULL) = 1445675009
16:23:29 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:29 write(2, "[libupu][16:23:29]: handle_event() => sEvent(32), connect UPU server failed, errno:111 error:'Connection refused'\n", 115) = 115
16:23:29 close(39) = 0
16:23:29 time(NULL) = 1445675009
16:23:29 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:29 write(2, "[libupu][16:23:29]: handle_event() => back to Initial state.\n", 61) = 61
16:23:29 epoll_wait(48, {}, 32, 3) = 0
16:23:29 clock_gettime(CLOCK_MONOTONIC, {160957, 31696245}) = 0
16:23:29 gettimeofday({1445675009, 623304}, NULL) = 0
16:23:29 time(NULL) = 1445675009
16:23:29 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:29 write(2, "[libupu][16:23:29]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
16:23:29 gettimeofday({1445675009, 623796}, NULL) = 0
16:23:29 write(6, "\260oM\t", 4) = 4
16:23:29 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\372\201\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94da028\n", 126, 0) = 126
16:23:29 nanosleep({4, 0},
NULL) = 0
16:23:33 clock_gettime(CLOCK_MONOTONIC, {160961, 32989311}) = 0
16:23:33 gettimeofday({1445675013, 624618}, NULL) = 0
16:23:33 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 39
16:23:33 fcntl64(39, F_GETFL) = 0x2 (flags O_RDWR)
16:23:33 fcntl64(39, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:23:33 connect(39, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:33 epoll_ctl(48, EPOLL_CTL_ADD, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:33 time(NULL) = 1445675013
16:23:33 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:33 write(2, "[libupu][16:23:33]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
16:23:33 gettimeofday({1445675013, 625662}, NULL) = 0
16:23:33 write(6, "\260oM\t", 4) = 4
16:23:33 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\372\205\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94da028 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
16:23:33 time(NULL) = 1445675013
16:23:33 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:33 write(2, "[libupu][16:23:33]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
16:23:33 clock_gettime(CLOCK_MONOTONIC, {160961, 34940043}) = 0
16:23:33 gettimeofday({1445675013, 626540}, NULL) = 0
16:23:33 clock_gettime(CLOCK_MONOTONIC, {160961, 35142558}) = 0
16:23:33 gettimeofday({1445675013, 626747}, NULL) = 0
16:23:33 epoll_wait(48, {{EPOLLERR|EPOLLHUP, {u32=39, u64=39}}}, 32, 4) = 1
16:23:33 clock_gettime(CLOCK_MONOTONIC, {160961, 35424775}) = 0
16:23:33 gettimeofday({1445675013, 627028}, NULL) = 0
16:23:33 getsockopt(39, SOL_SOCKET, SO_ERROR, [6222784223170789487], [4]) = 0
16:23:33 epoll_ctl(48, EPOLL_CTL_DEL, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:33 time(NULL) = 1445675013
16:23:33 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:33 write(2, "[libupu][16:23:33]: handle_event() => sEvent(32), connect UPU server failed, errno:111 error:'Connection refused'\n", 115) = 115
16:23:33 close(39) = 0
16:23:33 time(NULL) = 1445675013
16:23:33 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:33 write(2, "[libupu][16:23:33]: handle_event() => back to Initial state.\n", 61) = 61
16:23:33 epoll_wait(48, {}, 32, 3) = 0
16:23:33 clock_gettime(CLOCK_MONOTONIC, {160961, 39835540}) = 0
16:23:33 gettimeofday({1445675013, 631445}, NULL) = 0
16:23:33 time(NULL) = 1445675013
16:23:33 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:33 write(2, "[libupu][16:23:33]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
16:23:33 gettimeofday({1445675013, 631926}, NULL) = 0
16:23:33 write(6, "\260oM\t", 4) = 4
16:23:33 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\372\205\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94da028\n", 126, 0) = 126
16:23:33 nanosleep({4, 0},
NULL) = 0
16:23:37 clock_gettime(CLOCK_MONOTONIC, {160965, 41087982}) = 0
16:23:37 gettimeofday({1445675017, 632710}, NULL) = 0
16:23:37 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 39
16:23:37 fcntl64(39, F_GETFL) = 0x2 (flags O_RDWR)
16:23:37 fcntl64(39, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:23:37 connect(39, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:37 epoll_ctl(48, EPOLL_CTL_ADD, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:37 time(NULL) = 1445675017
16:23:37 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:37 write(2, "[libupu][16:23:37]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
16:23:37 gettimeofday({1445675017, 633856}, NULL) = 0
16:23:37 write(6, "\320\4\240V", 4) = 4
16:23:37 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\372\211\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94da028 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
16:23:37 time(NULL) = 1445675017
16:23:37 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:37 write(2, "[libupu][16:23:37]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
16:23:37 clock_gettime(CLOCK_MONOTONIC, {160965, 43210630}) = 0
16:23:37 gettimeofday({1445675017, 634818}, NULL) = 0
16:23:37 clock_gettime(CLOCK_MONOTONIC, {160965, 43395712}) = 0
16:23:37 gettimeofday({1445675017, 635001}, NULL) = 0
16:23:37 epoll_wait(48, {{EPOLLERR|EPOLLHUP, {u32=39, u64=39}}}, 32, 3) = 1
16:23:37 clock_gettime(CLOCK_MONOTONIC, {160965, 43690915}) = 0
16:23:37 gettimeofday({1445675017, 635298}, NULL) = 0
16:23:37 getsockopt(39, SOL_SOCKET, SO_ERROR, [6222784223170789487], [4]) = 0
16:23:37 epoll_ctl(48, EPOLL_CTL_DEL, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:37 time(NULL) = 1445675017
16:23:37 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:37 write(2, "[libupu][16:23:37]: handle_event() => sEvent(32), connect UPU server failed, errno:111 error:'Connection refused'\n", 115) = 115
16:23:37 close(39) = 0
16:23:37 time(NULL) = 1445675017
16:23:37 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:37 write(2, "[libupu][16:23:37]: handle_event() => back to Initial state.\n", 61) = 61
16:23:37 epoll_wait(48, {}, 32, 3) = 0
16:23:37 clock_gettime(CLOCK_MONOTONIC, {160965, 48145912}) = 0
16:23:37 gettimeofday({1445675017, 639754}, NULL) = 0
16:23:37 time(NULL) = 1445675017
16:23:37 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:37 write(2, "[libupu][16:23:37]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
16:23:37 gettimeofday({1445675017, 640222}, NULL) = 0
16:23:37 write(6, "\320\4\240V", 4) = 4
16:23:37 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\372\211\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94da028\n", 126, 0) = 126
16:23:37 nanosleep({4, 0},
NULL) = 0
16:23:41 clock_gettime(CLOCK_MONOTONIC, {160969, 49427437}) = 0
16:23:41 gettimeofday({1445675021, 641049}, NULL) = 0
16:23:41 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 39
16:23:41 fcntl64(39, F_GETFL) = 0x2 (flags O_RDWR)
16:23:41 fcntl64(39, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:23:41 connect(39, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:41 epoll_ctl(48, EPOLL_CTL_ADD, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:41 time(NULL) = 1445675021
16:23:41 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:41 write(2, "[libupu][16:23:41]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
16:23:41 gettimeofday({1445675021, 642233}, NULL) = 0
16:23:41 write(6, "\320\4\240V", 4) = 4
16:23:41 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\372\215\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94da028 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
16:23:41 time(NULL) = 1445675021
16:23:41 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:41 write(2, "[libupu][16:23:41]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
16:23:41 clock_gettime(CLOCK_MONOTONIC, {160969, 51633490}) = 0
16:23:41 gettimeofday({1445675021, 643243}, NULL) = 0
16:23:41 clock_gettime(CLOCK_MONOTONIC, {160969, 51823950}) = 0
16:23:41 gettimeofday({1445675021, 643432}, NULL) = 0
16:23:41 epoll_wait(48, {{EPOLLERR|EPOLLHUP, {u32=39, u64=39}}}, 32, 3) = 1
16:23:41 clock_gettime(CLOCK_MONOTONIC, {160969, 52155839}) = 0
16:23:41 gettimeofday({1445675021, 643768}, NULL) = 0
16:23:41 getsockopt(39, SOL_SOCKET, SO_ERROR, [6222784223170789487], [4]) = 0
16:23:41 epoll_ctl(48, EPOLL_CTL_DEL, 39, {EPOLLOUT, {u32=39, u64=39}}) = 0
16:23:41 time(NULL) = 1445675021
16:23:41 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:41 write(2, "[libupu][16:23:41]: handle_event() => sEvent(32), connect UPU server failed, errno:111 error:'Connection refused'\n", 115) = 115
16:23:41 close(39) = 0
16:23:41 time(NULL) = 1445675021
16:23:41 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:41 write(2, "[libupu][16:23:41]: handle_event() => back to Initial state.\n", 61) = 61
16:23:41 epoll_wait(48, {}, 32, 3) = 0
16:23:41 clock_gettime(CLOCK_MONOTONIC, {160969, 56678893}) = 0
16:23:41 gettimeofday({1445675021, 648291}, NULL) = 0
16:23:41 time(NULL) = 1445675021
16:23:41 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:41 write(2, "[libupu][16:23:41]: upu_client_loop() => event_base_dispatch [out]\n", 67) = 67
16:23:41 gettimeofday({1445675021, 648806}, NULL) = 0
16:23:41 write(6, "\320\4\240V", 4) = 4
16:23:41 send(18, "\3\356\0\0\0\7\0\0\0\0\0n\0\0\0\0\5\0l!\350\372\215\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_loop exit abnormal! ClientSeesion:0x94da028\n", 126, 0) = 126
16:23:41 nanosleep({4, 0},
NULL) = 0
16:23:45 clock_gettime(CLOCK_MONOTONIC, {160973, 58030107}) = 0
16:23:45 gettimeofday({1445675025, 649681}, NULL) = 0
16:23:45 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 59
16:23:45 fcntl64(59, F_GETFL) = 0x2 (flags O_RDWR)
16:23:45 fcntl64(59, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:23:45 connect(59, {sa_family=AF_INET, sin_port=htons(2100), sin_addr=inet_addr("172.16.185.136")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:45 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLOUT, {u32=59, u64=59}}) = 0
16:23:45 time(NULL) = 1445675025
16:23:45 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:45 write(2, "[libupu][16:23:45]: connect_server() => bufferevent_socket_connect Success! enter Connecting state.\n", 100) = 100
16:23:45 gettimeofday({1445675025, 650897}, NULL) = 0
16:23:45 write(6, "x\4\340V", 4) = 4
16:23:45 send(18, "\3\356\0\0\0\7\0\0\0\0\0\200\0\0\0\0\5\0~!\350\372\221\0\7\4\335\2[pid]:3713 [UpuWrapper]: [ThreadLoop] upu_client_connect ClientSeesion:0x94da028 IP:172.16.185.136, port:2100 \n", 144, 0) = 144
16:23:45 time(NULL) = 1445675025
16:23:45 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:45 write(2, "[libupu][16:23:45]: upu_client_loop() => event_base_dispatch [in]\n", 66) = 66
16:23:45 clock_gettime(CLOCK_MONOTONIC, {160973, 60319148}) = 0
16:23:45 gettimeofday({1445675025, 651930}, NULL) = 0
16:23:45 clock_gettime(CLOCK_MONOTONIC, {160973, 60510805}) = 0
16:23:45 gettimeofday({1445675025, 652116}, NULL) = 0
16:23:45 epoll_wait(48, {{EPOLLOUT, {u32=59, u64=59}}}, 32, 3) = 1
16:23:45 clock_gettime(CLOCK_MONOTONIC, {160973, 60808691}) = 0
16:23:45 gettimeofday({1445675025, 652415}, NULL) = 0
16:23:45 getsockopt(59, SOL_SOCKET, SO_ERROR, [6222784223170789376], [4]) = 0
16:23:45 time(NULL) = 1445675025
16:23:45 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:45 write(2, "[libupu][16:23:45]: handle_event() => sEvent(128), UPU connect Success! enter Connected state.\n", 95) = 95
16:23:45 time(NULL) = 1445675025
16:23:45 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:45 write(2, "[libupu][16:23:45]: handle_event() => ### enter CallBack ### [CONNECTED] nRspType(0)\n", 86) = 86
16:23:45 gettimeofday({1445675025, 653399}, NULL) = 0
16:23:45 write(6, "x\4\340V", 4) = 4
16:23:45 send(18, "\3\356\0\0\0\7\0\0\0\0\0\211\0\0\0\0\5\0\207!\350\372\221\0\7\4\335\2[pid]:3713 [UpuWrapper]: [UpuMsgCallBack] recive upu callback msg(1),resultType:0, nResultCount:0, arg point:0x94d4628 \n", 153, 0) = 153
16:23:45 gettimeofday({1445675025, 653944}, NULL) = 0
16:23:45 write(6, "x\4\340V", 4) = 4
16:23:45 send(18, "\3\356\0\0\0\7\0\0\0\0\0y\0\0\0\0\5\0w!\350\372\221\0\7\4\335\3[pid]:3713 [UpuWrapper]: [UpuClientMsgCallBack] ClientSeesion:0x94da028 recive upu connect succ msg(1) \n", 137, 0) = 137
16:23:45 time(NULL) = 1445675025
16:23:45 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:45 write(2, "[libupu][16:23:45]: handle_event() => set 10s READ timer for Heartbeat.\n", 72) = 72
16:23:45 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN|EPOLLOUT, {u32=59, u64=59}}) = 0
16:23:45 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:45 epoll_wait(48, {}, 32, 3) = 0
16:23:45 clock_gettime(CLOCK_MONOTONIC, {160973, 66717197}) = 0
16:23:45 gettimeofday({1445675025, 658330}, NULL) = 0
16:23:45 epoll_wait(48,
{}, 32, 9995) = 0
16:23:55 clock_gettime(CLOCK_MONOTONIC, {160983, 71186334}) = 0
16:23:55 gettimeofday({1445675035, 662790}, NULL) = 0
16:23:55 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:55 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:55 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:55 time(NULL) = 1445675035
16:23:55 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:23:55 write(2, "[libupu][16:23:55]: handle_event() => sEvent(65), Heartbeat timeout 0 times.\n", 77) = 77
16:23:55 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLOUT, {u32=59, u64=59}}) = 0
16:23:55 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN|EPOLLOUT, {u32=59, u64=59}}) = 0
16:23:55 epoll_wait(48, {{EPOLLOUT, {u32=59, u64=59}}}, 32, 10000) = 1
16:23:55 clock_gettime(CLOCK_MONOTONIC, {160983, 72274769}) = 0
16:23:55 gettimeofday({1445675035, 663870}, NULL) = 0
16:23:55 writev(59, [{"\0224Vx\0\0\0\0\0\0\0\2\0\0\0\0", 16}], 1) = 16
16:23:55 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:55 epoll_wait(48, {{EPOLLIN, {u32=59, u64=59}}}, 32, 9999) = 1
16:23:55 clock_gettime(CLOCK_MONOTONIC, {160983, 73025977}) = 0
16:23:55 gettimeofday({1445675035, 664664}, NULL) = 0
16:23:55 ioctl(59, FIONREAD, [16]) = 0
16:23:55 readv(59, [{"\0224Vx\0\0\0\0\0\0\0\3\0\0\0\0", 16}], 1) = 16
16:23:55 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:55 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:23:55 epoll_wait(48,
{}, 32, 10000) = 0
16:24:05 clock_gettime(CLOCK_MONOTONIC, {160993, 83205102}) = 0
16:24:05 gettimeofday({1445675045, 674823}, NULL) = 0
16:24:05 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:24:05 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:24:05 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:24:05 time(NULL) = 1445675045
16:24:05 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=405, ...}) = 0
16:24:05 write(2, "[libupu][16:24:05]: handle_event() => sEvent(65), Heartbeat timeout 0 times.\n", 77) = 77
16:24:05 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLOUT, {u32=59, u64=59}}) = 0
16:24:05 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN|EPOLLOUT, {u32=59, u64=59}}) = 0
16:24:05 epoll_wait(48, {{EPOLLOUT, {u32=59, u64=59}}}, 32, 10000) = 1
16:24:05 clock_gettime(CLOCK_MONOTONIC, {160993, 84503406}) = 0
16:24:05 gettimeofday({1445675045, 676115}, NULL) = 0
16:24:05 writev(59, [{"\0224Vx\0\0\0\0\0\0\0\2\0\0\0\0", 16}], 1) = 16
16:24:05 epoll_ctl(48, EPOLL_CTL_MOD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:24:05 epoll_wait(48, {{EPOLLIN, {u32=59, u64=59}}}, 32, 9999) = 1
16:24:05 clock_gettime(CLOCK_MONOTONIC, {160993, 85326294}) = 0
16:24:05 gettimeofday({1445675045, 676958}, NULL) = 0
16:24:05 ioctl(59, FIONREAD, [16]) = 0
16:24:05 readv(59, [{"\0224Vx\0\0\0\0\0\0\0\3\0\0\0\0", 16}], 1) = 16
16:24:05 epoll_ctl(48, EPOLL_CTL_DEL, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:24:05 epoll_ctl(48, EPOLL_CTL_ADD, 59, {EPOLLIN, {u32=59, u64=59}}) = 0
16:24:05 epoll_wait(48,
^C <unfinished ...>
Process 7474 detached
[root@upu_1 pas]#
相關文章
- 1. 公司報表配置系統總結
- 2. 【原創】CAS調研總結
- 3. 電商總結（七）緩存系統
- 4. Memcache緩存系統原理
- 5. 公司常見管理系統介紹（非原創）
- 6. 創業公司的技術總監，去上市公司面試，結果涼了
- 7. 揭祕阿里自研分佈式緩存系統 Tair
- 8. 瀏覽器緩存原理總結
- 9. HTTP緩存總結
- 10. redis緩存總結
- 更多相關文章...
- • Hibernate的二級緩存 - Hibernate教程
- • Hibernate的一級緩存 - Hibernate教程
- • Docker容器實戰(七) - 容器眼光下的文件系統
- • 算法總結-雙指針
相關標籤/搜索
每日一句
-
每一个你不满意的现在，都有一个你没有努力的曾经。
最新文章
- 1. No provider available from registry 127.0.0.1:2181 for service com.ddbuy.ser 解決方法
- 2. Qt5.7以上調用虛擬鍵盤(支持中文)，以及源碼修改(可拖動，水平縮放)
- 3. 軟件測試面試- 購物車功能測試用例設計
- 4. ElasticSearch（概念篇）：你知道的, 爲了搜索…
- 5. redux理解
- 6. gitee創建第一個項目
- 7. 支持向量機之硬間隔（一步步推導，通俗易懂）
- 8. Mysql 異步複製延遲的原因及解決方案
- 9. 如何在運行SEPM配置嚮導時將不可認的複雜數據庫密碼改爲簡單密碼
- 10. windows系統下tftp服務器使用
歡迎關注本站公眾號,獲取更多信息
相關文章
- 1. 公司報表配置系統總結
- 2. 【原創】CAS調研總結
- 3. 電商總結（七）緩存系統
- 4. Memcache緩存系統原理
- 5. 公司常見管理系統介紹（非原創）
- 6. 創業公司的技術總監，去上市公司面試，結果涼了
- 7. 揭祕阿里自研分佈式緩存系統 Tair
- 8. 瀏覽器緩存原理總結
- 9. HTTP緩存總結
- 10. redis緩存總結