임의로 주문서 상태가 '방문'으로 변경됨

pingpongworks commented 6 years ago

주문서번호 89785 사용자가 8번 탈의실에서 탈의중
2018년 1월 20일 14시17분에 방문 상태로 바뀜
옷장지기들은 상태를 바꾼 적 없음
2시30분 예약자였던 주문서번호 89799 사용자가 무인예약확인 중 변경됨

탈의중에서 방문으로 바뀐 시각은 14시 17분이고 2시 30분 예약자가 방문예약확인을 마친 시각은 14시 18분인 것으로 보아 전화번호 검색 중에 바뀐 것으로 예상됨.

pingpongworks commented 6 years ago

같은 날인 1월 20일에 발생한 탈의중 >> 방문 상태변경 오류입니다.

탈의실 6번에서 탈의중 이던 주문서번호 89624 사용자의 상태가 10시 01분 방문으로 바뀜.

본 오류의 경우에는 누가 방문예약확인을 하고 있었는지 확인은 되지 않았음

pingpongworks commented 6 years ago

같은날 발생한 이번 오류는 예약확인 중에 의류준비로 넘어간 경우입니다.

11시 예약자였던 주문서번호 89773 사용자가 방문을 한 후, 의류준비로 넘어갔습니다. 전화번호 검색 중이었는지, 예약확인을 눌렀는지 확인은 되지 않았습니다.

pingpongworks commented 6 years ago

주문서 90072 사용자가 치수측정하고 있는 중에

주문서 89659 사용자가 방문예약확인을 진행

주문서 90072 사용자의 상태가 방문으로 바뀜

pingpongworks commented 6 years ago

주문서 89882 사용자가 포장완료상태일 때

주문서번호 89879 사용자가 방문예약확인 중

주문서 89882 사용자의 상태가 방문으로 바뀜

그동안 `방문예약확인` 중 상태가 바뀐 오류가 여러 건이었는데, 옆에서 보고 있지 않은 이상  1. 전화번호를 검색할 때 변경되는지 2. 입장해주세요. 를 누를 때 변경되는지 3. 아니면 그냥 제멋대로 변경되는지 확인하기가 어려웠습니다.  가능하면 좀더 정확하게 어떤 상황에서 나타난 오류였는지 체크해볼 예정입니다.

pingpongworks commented 6 years ago

주문서번호 89639 사용자 탈의중에서 방문으로 바뀐 오류입니다. 봉사자가 실수로 바꾸었을 가능성도 있지만, 그런 가능성은 확인되지 않았고 오류로 인식되는 상황이라 일단 남깁니다.

pingpongworks commented 6 years ago

다들 현장에서 확인을 하진 못했지만 1시 47분(주문서번호 90129 사용자), 혹은 1시 48분(주문서번호 90206 사용자)에 일찍 방문하여 오후 첫 대여자가 방문확인 중에 오전 마지막 대여자였던 주문서번호 90248 대여자의 상태가 대여중이던 상태가 방문으로 바뀜

pingpongworks commented 6 years ago

주문서번호 90471 대여자가 `방문예약확인`을 위해 전화번호를 조회하던 도중

주문서번호 90611 대여자의 상태가 `방문`으로 바뀐 오류

이번 오류의 경우에는 90471 대여자가 전화번호 검색을 하는 중에 90611 대여자 상태가 `방문`으로 바뀐 것을 옷장지기가 눈으로 확인했다고 합니다. 초록색 방문예약확인 버튼을 누르기 전이었다고 합니다.

keedi commented 6 years ago

오히려 staff 보다 이쪽이 당시 유추할 수 있는 정황 자료가 조금 더 많은 것 같습니다. #169 #170 둘다 확인이 필요합니다.

keedi commented 6 years ago

2시30분 예약자였던 주문서번호 89799 사용자가 무인예약확인 중 변경됨

탈의중에서 방문으로 바뀐 시각은 14시 17분이고 2시 30분 예약자가 방문예약확인을 마친 시각은 14시 18분인 것으로 보아 전화번호 검색 중에 바뀐 것으로 예상됨.

제일 처음 이슈를 남겨주신 부분 중 89799 주문서를 언급하신 것은 어떤 연유이신지요? 조금 자세하게 설명 부탁드립니다.

pingpongworks commented 6 years ago

예상되는 정황을 시간 순으로 이야기해보겠습니다.

2시 30분 예약자인 89799가 14시 17분에 무인예약확인을 위해 전화번호 입력을 시도합니다.
8번 탈의실에 탈의중이던 89785의 상태가 14시 17분에 방문으로 바뀝니다.
89799는 예약확인을 마치고 14시 18분에 방문으로 바뀝니다.

누군가가 방문예약확인을 할 때, 탈의중인 대여자의 상태가 자동으로 방문으로 바뀌고 있는데, 그 누군가가 89799 주문서의 대여자라고 유추되어 언급한 것입니다.

keedi commented 6 years ago

무슨 의미인지 이해했습니다. 말씀하신 패턴으로 @yongbin 님께 요청해 현재 같이 mysql binlog를 분석중입니다. 말씀하신 것과 유사하게 다른 사람의 주문서 값을 변경하는 시점에 무언가 엉뚱한 사람의 주문서가 변경되는 정황을 확인중입니다. 정리되는대로 내용은 갱신하겠습니다.

keedi commented 6 years ago

사실 #170 과 본 이슈는 거의 동일한 이슈라고 사료됩니다. 물론 완전 별개의 이슈일 수도 있습니다만, 일단은 주문서의 상태가 임의로 예측할 수 없게 변경된다는 측면에서는 동일한 이슈일 가능성이 높습니다. 어찌됐든 본 이슈는 계속 일어날 가능성이 매우 높으므로 최대한 빨리 수정해야하는 이슈입니다. 다만 현재 코드베이스상 원인을 파악하기가 쉽지는 않아서 원인 또는 원인을 찾아낼 수 있는 방법을 찾고 있는 중입니다.

더불어 가장 마지막에 유사하게 주문서 상태가 임의로 변경된 경우는 언제쯤인지 기억나시는 바가 있으신지요? 마지막에 올려주신 1월 29일 이후에도 또 있었다면 정보 부탁드립니다. 이미 등록은 하셨지만 유사한 사례가 일어나면 계속 알려주시면 디버깅에 도움이 됩니다.

pingpongworks commented 6 years ago

마지막으로 보고된 유사 사례는 바로 어제인 2월 2일 (금) 오후 3시 45분입니다.

orders/91333 의 탈의중이던 상태가 방문으로 바뀐 사례입니다.

사실상 하루에 두세 번씩 일어나고 있는 현상이라 옷장지기들이 둔감해져서 모든 사례를 다 보고하고 있지 않은 상황입니다. 가능한한 모두 기록할 수 있도록 해보겠습니다.

yongbin commented 6 years ago

우선 지금까지 언급된 모든 케이스에 DB binlog를 대조해서 반복적으로 나타나는 패턴이 있는지를 확인했습니다.

case 1 : https://github.com/opencloset/monitor/issues/169#issue-290168368

89785 주문서가 탈의08(27)에서 방문(13)으로 잘못 상태가 변경된 후에 89799 주문서가 방문(13)으로 상태가 변경됨

/*!*/;
# at 1100436
#180120 14:17:49 server id 1  end_log_pos 1100620       Query   thread_id=3625  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516425469/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-20 14:17:49' WHERE ( `id` = '89785' )§Ó^T<83>
/*!*/;
# at 1100620
#180120 14:17:49 server id 1  end_log_pos 1100651       Xid = 3109608
COMMIT/*!*/;
# at 1100651
#180120 14:18:18 server id 1  end_log_pos 1100739       Query   thread_id=6407  exec_time=0     error_code=0
SET TIMESTAMP=1516425498/*!*/;
BEGINháî
/*!*/;
# at 1100739
#180120 14:18:18 server id 1  end_log_pos 1100923       Query   thread_id=6407  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516425498/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-20 14:18:18' WHERE ( `id` = '89799' )ù/Þ<87>

case 2 : https://github.com/opencloset/monitor/issues/169#issuecomment-359148614

89624 주문서가 탈의06(25)에서 방문(13)으로 잘못 상태가 변경된 후에 89171 주문서가 방문(13)으로 상태가 변경됨

/*!*/;
# at 169453
#180120 10:01:32 server id 1  end_log_pos 169637        Query   thread_id=3920  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516410092/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-20 10:01:32' WHERE ( `id` = '89624' )Ãâ<9b>_
/*!*/;
# at 169637
#180120 10:01:32 server id 1  end_log_pos 169668        Xid = 3009987
COMMIT/*!*/;
# at 169668
#180120 10:01:45 server id 1  end_log_pos 169756        Query   thread_id=4873  exec_time=0     error_code=0
SET TIMESTAMP=1516410105/*!*/;
BEGIN<92>^HÑY
/*!*/;
# at 169756
#180120 10:01:45 server id 1  end_log_pos 169940        Query   thread_id=4873  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516410105/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-20 10:01:45' WHERE ( `id` = '89171' )Æ¹Ú6

case 3 : https://github.com/opencloset/monitor/issues/169#issuecomment-359148875

89773 주문서가 방문예약(14)에서 의류준비(17)으로 잘못 상태가 변경됨(동일시점 부근에 유사한 상태변경이 발생하지 않았음)

/*!*/;
# at 468416
#180120 10:52:53 server id 1  end_log_pos 468447        Xid = 3051210
COMMIT/*!*/;
# at 468447
#180120 10:52:56 server id 1  end_log_pos 468535        Query   thread_id=5255  exec_time=0     error_code=0
SET TIMESTAMP=1516413176/*!*/;
BEGINÌ^Gn<9a>
/*!*/;
# at 468535
#180120 10:52:56 server id 1  end_log_pos 468719        Query   thread_id=5255  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516413176/*!*/;
UPDATE `order` SET `status_id` = '17', `update_date` = '2018-01-20 10:52:56' WHERE ( `id` = '89773' )<9f>»®<9b>
/*!*/;
# at 468719
#180120 10:52:56 server id 1  end_log_pos 468750        Xid = 3051380
COMMIT/*!*/;
# at 468750
#180120 10:53:16 server id 1  end_log_pos 468830        Query   thread_id=2525  exec_time=0     error_code=0
SET TIMESTAMP=1516413196/*!*/;
BEGINÚ½i^Z

case 4 : https://github.com/opencloset/monitor/issues/169#issuecomment-359686405

90072 주문서가 치수측정(16)에서 방문(13)으로 잘못 상태가 변경된 후에 89659 주문서가 방문(13)으로 상태가 변경됨

## 90072 
/*!*/;
# at 1563569
#180123 14:46:16 server id 1  end_log_pos 1563753   Query   thread_id=7217  exec_time=0 error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516686376/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-23 14:46:16' WHERE ( `id` = '90072' )¡
/*!*/;
# at 1563753
#180123 14:46:16 server id 1  end_log_pos 1563784   Xid = 4558465
COMMIT/*!*/;
# at 1563784
#180123 14:46:18 server id 1  end_log_pos 1563875   Query   thread_id=7057  exec_time=0 error_code=0
SET TIMESTAMP=1516686378/*!*/;
BEGINÊ¹ÜH
/*!*/;
# at 1563875
#180123 14:46:18 server id 1  end_log_pos 1564023   Query   thread_id=7057  exec_time=0 error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516686378/*!*/;
UPDATE `user_info` SET `bust` = '100' WHERE ( `id` = '87920' )å¥<
/*!*/;
# at 1564023
#180123 14:46:18 server id 1  end_log_pos 1564054   Xid = 4558497
COMMIT/*!*/;
# at 1564054
#180123 14:46:23 server id 1  end_log_pos 1564145   Query   thread_id=9334  exec_time=0 error_code=0
SET TIMESTAMP=1516686383/*!*/;
BEGIN¨S
/*!*/;
# at 1564145
#180123 14:46:23 server id 1  end_log_pos 1564293   Query   thread_id=9334  exec_time=0 error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516686383/*!*/;
UPDATE `user_info` SET `waist` = '85' WHERE ( `id` = '87920' )Ð»=Ò
/*!*/;
# at 1564293
#180123 14:46:23 server id 1  end_log_pos 1564324   Xid = 4558611
COMMIT/*!*/;
# at 1564324
#180123 14:46:30 server id 1  end_log_pos 1564415   Query   thread_id=9334  exec_time=0 error_code=0
SET TIMESTAMP=1516686390/*!*/;
BEGINãä
/*!*/;
# at 1564415
#180123 14:46:30 server id 1  end_log_pos 1564566   Query   thread_id=9334  exec_time=0 error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516686390/*!*/;
UPDATE `user_info` SET `topbelly` = '95' WHERE ( `id` = '87920' )õþeJ
/*!*/;
# at 1564566
#180123 14:46:30 server id 1  end_log_pos 1564597   Xid = 4558732
COMMIT/*!*/;
# at 1564597
#180123 14:46:36 server id 1  end_log_pos 1564688   Query   thread_id=9334  exec_time=0 error_code=0
SET TIMESTAMP=1516686396/*!*/;
BEGINÎõ¡
/*!*/;
# at 1564688
#180123 14:46:36 server id 1  end_log_pos 1564836   Query   thread_id=9334  exec_time=0 error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516686396/*!*/;
UPDATE `user_info` SET `belly` = '97' WHERE ( `id` = '87920' )@Up
/*!*/;
# at 1564836
#180123 14:46:36 server id 1  end_log_pos 1564867   Xid = 4558857
COMMIT/*!*/;
# at 1564867
#180123 14:46:38 server id 1  end_log_pos 1564955   Query   thread_id=9334  exec_time=0 error_code=0
SET TIMESTAMP=1516686398/*!*/;
BEGINqXù*
/*!*/;
# at 1564955
#180123 14:46:38 server id 1  end_log_pos 1565139   Query   thread_id=9334  exec_time=0 error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516686398/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-23 14:46:38' WHERE ( `id` = '89659' )±Ë:

case 5 : https://github.com/opencloset/monitor/issues/169#issuecomment-359689472

89882 주문서가 포장완료(44)에서 방문(13)으로 잘못 상태가 변경된 후에 89879 주문서가 방문(13)으로 상태가 변경됨

/*!*/;
# at 1036726
#180122 11:52:39 server id 1  end_log_pos 1036910       Query   thread_id=6540  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516589559/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-22 11:52:39' WHERE ( `id` = '89882' )ßûY¢
/*!*/;
# at 1036910
#180122 11:52:39 server id 1  end_log_pos 1037049       Query   thread_id=6540  exec_time=0     error_code=0
SET TIMESTAMP=1516589559/*!*/;
UPDATE `clothes` SET `status_id` = '13' WHERE ( `id` = '31464' )ê`wµ
/*!*/;
# at 1037049
#180122 11:52:39 server id 1  end_log_pos 1037188       Query   thread_id=6540  exec_time=0     error_code=0
SET TIMESTAMP=1516589559/*!*/;
UPDATE `clothes` SET `status_id` = '13' WHERE ( `id` = '31493' )>úâ_
/*!*/;
# at 1037188
#180122 11:52:39 server id 1  end_log_pos 1037327       Query   thread_id=6540  exec_time=0     error_code=0
SET TIMESTAMP=1516589559/*!*/;
UPDATE `clothes` SET `status_id` = '13' WHERE ( `id` = '30968' )îhR<98>
/*!*/;
# at 1037327
#180122 11:52:39 server id 1  end_log_pos 1037358       Xid = 3737414
COMMIT/*!*/;
# at 1037358
#180122 11:52:59 server id 1  end_log_pos 1037446       Query   thread_id=6292  exec_time=0     error_code=0
SET TIMESTAMP=1516589579/*!*/;
BEGINµ^V<8f>^Q
/*!*/;
# at 1037446
#180122 11:52:59 server id 1  end_log_pos 1037630       Query   thread_id=6292  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516589579/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-22 11:52:59' WHERE ( `id` = '89879' )ÚW\^F

case 6 : https://github.com/opencloset/monitor/issues/169#issuecomment-359747618

89639 주문서가 탈의09(28)에서 포장(18)으로 잘못 상태가 변경된 후에 89368 주문서가 포장(18)으로 상태가 변경됨

/*!*/;
# at 880256
#180121 14:13:33 server id 1  end_log_pos 880440        Query   thread_id=6816  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516511613/*!*/;
UPDATE `order` SET `status_id` = '18', `update_date` = '2018-01-21 14:13:33' WHERE ( `id` = '89639' )©5ÕÀ
/*!*/;
# at 880440
#180121 14:13:33 server id 1  end_log_pos 880471        Xid = 3401127
COMMIT/*!*/;
# at 880471
#180121 14:13:34 server id 1  end_log_pos 880559        Query   thread_id=5839  exec_time=0     error_code=0
SET TIMESTAMP=1516511614/*!*/;
BEGIN°^]^PJ
/*!*/;
# at 880559
#180121 14:13:34 server id 1  end_log_pos 880743        Query   thread_id=5839  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516511614/*!*/;
UPDATE `order` SET `status_id` = '18', `update_date` = '2018-01-21 14:13:34' WHERE ( `id` = '89368' )f<82>#:

case 7 : https://github.com/opencloset/monitor/issues/169#issuecomment-360032329

90248 주문서가 대여중(2)에서 방문(13)으로 잘못 상태가 변경된 후에 90129,90129 주문서가 방문(13)으로 상태가 변경됨

90248 변경이후에 다수의 주문서가 방문으로 변경되므로 중요한 케이스로 생각됨(용빈)

/*!*/;
# at 1315121
#180124 13:47:45 server id 1  end_log_pos 1315305       Query   thread_id=10365 exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516769265/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-24 13:47:45' WHERE ( `id` = '90248' )<85>Ä%<94>
/*!*/;
# at 1315305
#180124 13:47:45 server id 1  end_log_pos 1315442       Query   thread_id=10365 exec_time=0     error_code=0
SET TIMESTAMP=1516769265/*!*/;
UPDATE `clothes` SET `status_id` = '13' WHERE ( `id` = '912' )TG^T^D
/*!*/;
# at 1315442
#180124 13:47:45 server id 1  end_log_pos 1315581       Query   thread_id=10365 exec_time=0     error_code=0
SET TIMESTAMP=1516769265/*!*/;
UPDATE `clothes` SET `status_id` = '13' WHERE ( `id` = '23866' )xü¤^P
/*!*/;
# at 1315581
#180124 13:47:45 server id 1  end_log_pos 1315720       Query   thread_id=10365 exec_time=0     error_code=0
SET TIMESTAMP=1516769265/*!*/;
UPDATE `clothes` SET `status_id` = '13' WHERE ( `id` = '31253' )<81>§Ý^^
/*!*/;
# at 1315720
#180124 13:47:45 server id 1  end_log_pos 1315751       Xid = 5117839
COMMIT/*!*/;
# at 1315751
#180124 13:47:59 server id 1  end_log_pos 1315839       Query   thread_id=9698  exec_time=0     error_code=0
SET TIMESTAMP=1516769279/*!*/;
BEGIN<84>ÙÆ«
/*!*/;
# at 1315839
#180124 13:47:59 server id 1  end_log_pos 1316023       Query   thread_id=9698  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516769279/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-24 13:47:59' WHERE ( `id` = '90129' )é<82>^[f
/*!*/;
# at 1316023
#180124 13:47:59 server id 1  end_log_pos 1316054       Xid = 5117898
COMMIT/*!*/;
# at 1316054
#180124 13:48:19 server id 1  end_log_pos 1316142       Query   thread_id=9698  exec_time=0     error_code=0
SET TIMESTAMP=1516769299/*!*/;
BEGIN<81>x%Â
/*!*/;
# at 1316142
#180124 13:48:19 server id 1  end_log_pos 1316326       Query   thread_id=9698  exec_time=0     error_code=0
use `opencloset`/*!*/;
SET TIMESTAMP=1516769299/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-24 13:48:19' WHERE ( `id` = '90206' )¢<98>z<87>

case 8 : https://github.com/opencloset/monitor/issues/169#issuecomment-361196096

90611 주문서가 탈의10(29)에서 방문(13)으로 잘못 상태가 변경된 후에 90471 주문서가 방문(13)으로 상태가 변경됨

이 케이스는 잘못 파악된 케이스로 보임(용빈)

/*!*/;
# at 1735197
#180129 15:17:35 server id 1  end_log_pos 1735381 CRC32 0x82808e5a      Query   thread_id=13611 exec_time=0     error_code=0
SET TIMESTAMP=1517206655/*!*/;
UPDATE `order` SET `status_id` = '13', `update_date` = '2018-01-29 15:17:35' WHERE ( `id` = '90611' )
/*!*/;
# at 1735381
#180129 15:17:35 server id 1  end_log_pos 1735412 CRC32 0x88c4031f      Xid = 7524887
COMMIT/*!*/;
# at 1735412
#180129 15:17:43 server id 1  end_log_pos 1735492 CRC32 0x912e32c8      Query   thread_id=14015 exec_time=0     error_code=0
SET TIMESTAMP=1517206663/*!*/;
BEGIN
/*!*/;
# at 1735492
#180129 15:17:43 server id 1  end_log_pos 1735680 CRC32 0x6f658a9e      Query   thread_id=14015 exec_time=0     error_code=0
SET TIMESTAMP=1517206663/*!*/;
UPDATE `order` SET `late_fee_pay_with` = '카드', `update_date` = '2018-01-29 15:17:43' WHERE ( `id` = '89505' )
/*!*/;
# at 1735680
#180129 15:17:43 server id 1  end_log_pos 1735711 CRC32 0xbb7b7f42      Xid = 7525129
COMMIT/*!*/;
# at 1735711
#180129 15:17:48 server id 1  end_log_pos 1735799 CRC32 0xce03ce55      Query   thread_id=13039 exec_time=0     error_code=0
SET TIMESTAMP=1517206668/*!*/;
BEGIN
/*!*/;
# at 1735799
# at 1735831
#180129 15:17:48 server id 1  end_log_pos 1735831 CRC32 0x0e023078      Intvar
SET INSERT_ID=485616/*!*/;
#180129 15:17:48 server id 1  end_log_pos 1736143 CRC32 0x05523be5      Query   thread_id=13039 exec_time=0     error_code=0
SET TIMESTAMP=1517206668/*!*/;
INSERT INTO `order_detail` ( `create_date`, `desc`, `final_price`, `name`, `order_id`, `pay_with`, `price`, `stage`) VALUES ( '2018-01-29 15:17:48', '32,000원 x 20% x 2일', '12800', '연장료', '89505', '카드', '6400', '1' )
/*!*/;
# at 1736143
#180129 15:17:48 server id 1  end_log_pos 1736365 CRC32 0x6f965d4b      Query   thread_id=13039 exec_time=0     error_code=0
SET TIMESTAMP=1517206668/*!*/;
UPDATE `order` SET `return_date` = '2018-01-29T15:17:48', `status_id` = '9', `update_date` = '2018-01-29 15:17:48' WHERE ( `id` = '89505' )
/*!*/;
# at 1736365
#180129 15:17:48 server id 1  end_log_pos 1736503 CRC32 0x6187f8a2      Query   thread_id=13039 exec_time=0     error_code=0
SET TIMESTAMP=1517206668/*!*/;
UPDATE `clothes` SET `status_id` = '9' WHERE ( `id` = '22471' )
/*!*/;
# at 1736503
#180129 15:17:48 server id 1  end_log_pos 1736640 CRC32 0xa7242588      Query   thread_id=13039 exec_time=0     error_code=0
SET TIMESTAMP=1517206668/*!*/;
UPDATE `clothes` SET `status_id` = '9' WHERE ( `id` = '9052' )

우선 대부분의 경우 후속 방문상태로 변경이 잘못된 방문상태로의 변경을 유발하는것 처럼 보이지만, 후속상태에 영향을 받는 경우가 꼭 방문이 아닌 케이스(케이스 6 : https://github.com/opencloset/monitor/issues/169#issuecomment-359747618) 도 존재하며 후속 상태변경과 관계없이 상태가 변경되는 경우들도 보이기때문에 단정할수는 없는 상황입니다.

pingpongworks commented 6 years ago

90611 주문서가 탈의10(29)에서 방문(13)으로 잘못 상태가 변경된 후에 90471 주문서가 방문(13)으로 상태가 변경됨 이 케이스는 잘못 파악된 케이스로 보임(용빈)

@yongbin 두 주문서의 상태변경 시각이 차이가 나는 걸로 보아, 위 케이스는 잘못 파악된 게 맞는 듯 합니다. 사례에서 제외시켜도 되겠습니다.

yongbin commented 6 years ago

@pingpongworks 넵 확인해 주셔서 감사합니다. 다른건들과는 패턴이 조금 다르지만 아직 명확하게 인과관계가 파악되지는 않아서 같이 고려는 하고 있습니다.

위에 파악된 케이스들을 요약하면 다음과 같습니다.

89785 주문서가 탈의08(27)에서 방문(13)으로 잘못 상태가 변경된 후에 89799 주문서가 방문(13)으로 상태가 변경됨
89624 주문서가 탈의06(25)에서 방문(13)으로 잘못 상태가 변경된 후에 89171 주문서가 방문(13)으로 상태가 변경됨
89773 주문서가 방문예약(14)에서 의류준비(17)으로 잘못 상태가 변경됨(동일시점 부근에 유사한 상태변경이 발생하지 않았음)
90072 주문서가 치수측정(16)에서 방문(13)으로 잘못 상태가 변경된 후에 89659 주문서가 방문(13)으로 상태가 변경됨
89882 주문서가 포장완료(44)에서 방문(13)으로 잘못 상태가 변경된 후에 89879 주문서가 방문(13)으로 상태가 변경됨
89639 주문서가 탈의09(28)에서 포장(18)으로 잘못 상태가 변경된 후에 89368 주문서가 포장(18)으로 상태가 변경됨
90248 주문서가 대여중(2)에서 방문(13)으로 잘못 상태가 변경된 후에 90129,90129 주문서가 방문(13)으로 상태가 변경됨(중요)
90611 주문서가 탈의10(29)에서 방문(13)으로 잘못 상태가 변경된 후에 90471 주문서가 방문(13)으로 상태가 변경됨(INVALID?)

잘못된 상태의 변경을 A 라고 보고 직후 다른 주문서에 동일한 상태변경을 B 라고 본다면

대체적으로 A가 발생한 뒤 B가 발생하는 상황입니다.
하지만 인과관계를 이야기하기위해서는 B가 발생한 뒤 A가 발생해야하는데 현재는 시간순서가 반대이기때문에 둘 사이에 인과관계를 직접적으로 이야기하기 어려운 상황입니다
다만 대부분의 경우 A와 B 사이에 시간텀이 길지 않은점으로 미루어볼때 우리에게 관측된 B가 발생하기 사전단계의 어떤 행동(예를들면 위에서 반복적으로 언급되는 전화번호찾기등)이 A와 인과관계가 있을수 있다는것은 말이되는 추측입니다.
마지막으로 한가지 간과하면 안되는점은, 위 사례들중 후속 상태변경과 관계없이 상태변경이 이루어진 경우도 2건 존재한다는 점입니다. 이 점으로 미루어보면 현재 우리가 생각하는 A후 B 발생이라는 가설은 다만 발견된 사례 일 뿐이고 훨씬 더 큰 차원에서 임의에 상태변경등이 발생하고 있을 가능성도 있습니다.

pingpongworks commented 6 years ago

orders/94061 3월 4일 (일) 오후 3시경 / 탈의중에서 방문으로 넘어가는 오류 발생 orders/94226 대여자가 예약확인시 바뀐 것으로 추정

pingpongworks commented 6 years ago

orders/94221 3월 3일 (토) 오전 10시 45분 경 / 탈의중에서 방문으로 넘어가는 오류 발생

pingpongworks commented 6 years ago

user/91667 2월 25일 (일) 오전 10시 40분 / 탈의중에서 방문으로 넘어가는 오류 발생

pingpongworks commented 6 years ago

orders/92307 2월 11일 (일) 오후 3시 49분 / 탈의중에서 방문으로 변경되는 오류 발생

pingpongworks commented 6 years ago

@aanoaa 임의로 주문서상태가 변경되는 오류가 잊을만하면 한번씩 발생하고 있습니다. 그동안 스태프들이 기록해두었던 오류들을 한꺼번에 정리하였습니다. 참고해주세요~

aanoaa commented 6 years ago

응답이 늦었습니다. 죄송합니다.

누군가가 방문예약 화면을 조작할때에 대여절차 중에 있는 임의의 주문서의 상태가 방문으로 변경되는 것 같은 상황입니다.

주문서의 상태가 바뀔 수 있는 곳은

monitor 방문예약 (본인)
- 방문예약 -> 방문 or 의류준비
staff 시간표 (staff)
- * -> *
staff orders/:id (staff)
- 포장완료 -> 대여중
- 대여중 -> 반납
- 대여중 -> 환불
monitor preparation (staff)
- 의류준비 -> 탈의/포장/수선
- 탈의 -> 의류준비/포장/수선
- 수선 -> 포장
staff 대여
- 포장 -> 포장완료
staff 포장완료 주문서 목록
- 포장완료 -> 결제대기

입니다.

이외에도 가상계좌 입금과 관련해서 주문서의 상태가 변경될 수 있습니다.

현재로서 시도해볼만한 조치로는

방문예약 -> 방문 으로 변경될때에 좀 더 자세한 로그를 남겨놓는 것
상태 변경을 요청하는 코드를 검토해보는 것

입니다.

aanoaa commented 6 years ago

방문예약 -> 방문 으로 변경될때에 로그를 남기도록 하였고, 방문예약 상태에서만 방문으로 상태를 변경할 수 있도록 예외처리를 하였습니다.

pingpongworks commented 6 years ago

@aanoaa 방문예약 상태에서만 방문으로 상태를 변경할 수 있도록 예외처리하는 것만으로도 방문으로 상태변경되는 오류가 많이 줄어들 거 같네요. 감사합니다^^

opencloset / monitor